Debugging Stored procedures

By | In MySQL | October 15th, 2010

Over the past several weeks, we’ve been working on debugging a stored procedure bug for a client. Coming from a software development background, I looked at the procedure like any piece of code — how can I debug the program and be able to use some means of knowing the values within the program while it’s running? In C, I’ve always used GDB, as well as Perl having it’s own debugger. Also useful are print statements! Those can be the most simplistic but also useful tools in debugging, especially in the case of a C program that’s so optimized that GDB gives you the famous “value optimized out” message, preventing you from knowing what the program is really doing. Stored procedures are a whole different matter than compiled or interpreted code. They are executing within the database. The line numbers in your source file you inevitably create the procedure with don’t match the line numbers of the procedure as stored by the database. Furthermore, if you are a developer of other languages, you will find debugging stored procedures to be a exercise in misery. You can load a stored procedure into MySQL, and as long as the SQL is syntactically correct, it will not catch things such as specifying variables that don’t exist– you will have the joy of discovering those during run-time– and most often the error message displayed will be of little use. How then, can you better observe the execution of a stored procedure? In some cases, you could run it with print statements and simply observe the output when the procedure is executed. But in our case, that was not a solution as the procedure had mostly DML statements and we needed something that was more precise. We needed something that not only allows you to display the values of variables, but also show you when the statement was executed. There is this very useful article on Dr. Dobbs, a concept that we expanded upon. The main idea of this article is that a temporary memory table is used during the execution of the stored procedure to insert stored procedure debug messages into, and being a memory table, won’t touch disk and will be as lightweight as possible. At the end of a debug session, these messages are copied from the temporary table into a permanent table with the same table definition. This gives you a means of reading the debug messages written during the execution of your stored procedure. We built upon the idea from the article and came up with these useful stored procedures that are easy to load and utilize in a stored procedure. They allow you to print any message that you want to, along with the time and the connection/thread ID of the thread executing the procedure– something that was invaluable in debugging what we thought at first was a race condition. Debugging stored procedures The following debugging procedures can be used within your stored procedures. First, each will be introduced, and then a more descriptive explanation on how they work will be provided, along with source code. Note that these procedures are also available github: setupProcLog() This procedure you run once at the beginning of your procedure to set up the the temporary table for storing messages in, as well as ensuring that there is a permanent log table. procLog() This is the procedure you call for each debug message. cleanup() This is the procedure you call at the end of your debugging session The code for each of these procedures:

As you can see, setupProcLog() first checks to see if the permanent logging table exists, and if not, creates it. The second create statement creates the temporary memory table for logging messages to. Note that ‘if exists’ is not sufficient for avoiding warnings that will cause your exception handler to be called in the event the table already exists and is even created specifying an ‘if exists’ condition. Also note that a storage engine is not specified for proclog. In this case, proclog should be a non-transactional table to avoid any issues with the stored procedure using the debugging procedures within a transaction– you don’t want all your debug messages rolled-back!

The procLog() procedure is what you use to log messages with. You can see an exception handler is set in case the table is not found, setupProcLog() is called to make sure the both the temporary and permanent log tables exist, as well as display a message that the temporary table has been set up. Then of course, in the case of no exception, the message is inserted into the table.

Finally, the cleanup() procedure copies all entries made during the session into the permanent logging table, then the temporary logging table is truncated. Note that this procedure just drops the temporary table, tmp_proclog. This is to allow you to be able to run setupProcLog() without a warning about tmp_proclog existing. Since all the data has been copied to proclog as well as being temporary table that will be re-created if setupProcLog() is called, dropping it works out well. These procedures are easy to use. Just load them into your MySQL instance:

In your procedure code, you are able to now log messages! First, you will call:

Then you can log message:

Or even with variables:

Note above the use of ifnull(). This is because concat() fails if the variable in the list being concatenated is is NULL. Now, for an actual procedure. The procedure shown below is for demonstration purposes and will show as succinctly as possible the problem we encountered. The issue was essentially that there is a stored procedure that has a number start of a transaction, a number insert statements that occur within a loop into tables relating to a single unique id and then a final check on the primary table to see if that unique id has been inserted already– and based on this, commits or rolls back the subsequent inserts. The procedure looked bullet-proof, and it seemed that there would be no way for any of the subsequent insert statements to ever be committed, but there was one problem: within the loop, there was a call to another stored procedure that also had it’s own call to start and commit a transaction. You cannot have nested transactions in MySQL, and this was the crux of the problem, and what the example procedure here will attempt to show, as well as show you how you can practically utilize the debugging procedures.

As you can see, the call to procLog() gives you the ability to see what line of the procedure was called. This all corresponds to the line numbers you have in whatever source file you use to add your stored procedure to your database from. As you just saw, there was a call to the someother_proc() procedure. In this case, someother_proc() contains a transaction which will demonstrate the problem with trying to attempted nested transactions– something that you should always be cognizant of in debugging stored procedures

Now, to actually run this procedure and see what is entred into the proclog table.

So, as can be seen, the status code returned is ‘1’, meaning that the user wasn’t inserted. How can this be? Well, now that the procLog() procedure is being utilized, you can query the table proclog

Also, randlog can be queried to see what the random value was:

Aha! BAIL was set to ‘1’ because of the random value being greater than .5, so the loop ended. This means that the subsequent insert statements should have not been committed, right?  (well, we know there’s a nested transaction, but for the sake of this example, let us forget about that momentarily) The users table should be empty, and it is:

The next table to check is userloop_count, it too should be empty:

Hmm, but it is not! How could this be? The status code was set to ‘1’, so the ROLLBACK having been issued would roll back all the previous insert statements. What else can we look at? Binary Log The binary log is like a closed circuit TV camera of your database– at least in terms of DML statements. Any statement that modifies your data will be found in your binary log. Not only that, you can see what thread issued the statement. The evidence is there for you to see! The following is cleaned up to make clearer: So, the first line below, the message “loop iteration #0” is inserted into proclog:

Next, the insertion into userloop_count is made:

The message indicating the call to someother_proc() is inserted into proclog:

Next, the crux of the problem! A COMMIT is issued. How can this be? Well, because there is a ‘BEGIN TRANSACTION’, which there was already a ‘BEGIN TRANSACTION’ issued in the calling procedure. Nested transactions are not supported, and when you issue a ‘BEGIN TRANSACTION’ within a transaction, it acts as an implicite ‘COMMIT’

So, now the problem is know and can be fixed accordingly! Summary This post was written to help those who are pulling their hair out debugging their stored procedures. This post was also written for those who might have come from more from a development role and might have an approach that is overly complex. When debugging stored procedures, here are some tips that will help: * binary log – look at this first when something seems awry. It is the closed-circuit TV recording of what happened with your database * utilize these logging procedures to debug your stored procedures * look closely at the data in the tables affected by your stored procedures You will develop an intuition for the types of issues stored procedures present over time. You just have to think a bit differently than with regular programming.

Contact Us

Leave a Reply

Your email address will not be published.
Required fields are marked (*).