Debugging SQL at the database

JeevesBond's picture

He has: 3,955 posts

Joined: Jun 2002

I needed a quick way to debug what PDO statements were being executed (and their parameters) by Drupal 7's DBTNG. I could have used the devel module, but am not a fan of it, also devel cannot -- at time of writing -- display the parameters passed to it.

So, the easiest way to get what's going on in the database is from the horses mouth, the database system itself. I'm using Postgres, so I'll cover that one first*:

Copy and paste the following to the command line:

sudo -u postgres pg_ctlcluster -o "-d 2" 8.3 main restart

The 8.3 is the version of Postgres and main is the name of the Postgres cluster to run (the latter will probably not need to be changed). Both the version and cluster name can be found by running ls /etc/postgres/ and ls /etc/postgres/8.3/ respectively.

Next, copy the following to the command line:

tail -f /var/log/postgresql/postgresql-8.3-main.log | grep -E ' |LOG:|DETAIL:'

Again, replace the 8.3 with your version of Postgres if necessary, also note that space is actually a tab character (create a new one by pressing Ctrl-v, then . Now Go and surf some pages on your Drupal 7 site! Smiling

This will output lots of information onto the command line. The output should look something like this:

2009-07-08 11:33:49 EDT LOG:  execute pdo_pgsql_stmt_4ab7ee78: SELECT u.*, s.* FROM users u INNER JOIN sessions s ON u.uid = s.uid WHERE s.sid = $1
2009-07-08 11:33:49 EDT DETAIL:  parameters: $1 = 'e789e2ce97522692be20fbc79011e047'
2009-07-08 11:33:49 EDT LOG:  execute pdo_pgsql_stmt_4ab99850: SELECT r.rid, r.name FROM role r INNER JOIN users_roles ur ON ur.rid = r.rid WHERE ur.uid = $1
2009-07-08 11:33:49 EDT DETAIL:  parameters: $1 = '1'
2009-07-08 11:33:49 EDT LOG:  execute pdo_pgsql_stmt_4ab9ab10: SELECT data, created, headers, expire, serialized FROM cache WHERE cid = $1
2009-07-08 11:33:49 EDT DETAIL:  parameters: $1 = 'variables'
2009-07-08 11:33:49 EDT LOG:  execute pdo_pgsql_stmt_4aba1ea8: SELECT data, created, headers, expire, serialized FROM cache_registry WHERE cid = $1
2009-07-08 11:33:49 EDT DETAIL:  parameters: $1 = 'hooks'
2009-07-08 11:33:50 EDT LOG:  execute pdo_pgsql_stmt_4aba1ea8: SELECT data, created, headers, expire, serialized FROM cache_registry WHERE cid = $1
2009-07-08 11:33:50 EDT DETAIL:  parameters: $1 = 'lookup_cache'
2009-07-08 11:33:50 EDT LOG:  execute pdo_pgsql_stmt_4a092d60: SELECT name, filename FROM system WHERE type = 'module' AND status = 1 ORDER BY weight ASC, name ASC
FROM
menu_router menu_router
WHERE  (path IN  ($1, $2, $3, $4, $5, $6))
ORDER BY fit DESC LIMIT 1 OFFSET 0

Once you've finished debugging, run:

sudo /etc/init.d/postgresql-8.3 restart

To get Postgres back to normal, otherwise it will generate massive log files and you'll be wondering where all your hard drive space went to! Smiling

* You'll also be needing Ubuntu, Debian or some other GNU/Linux variant, plus a little command line experience always helps.

a Padded Cell our articles site!

teammatt3's picture

He has: 2,102 posts

Joined: Sep 2003

Postgres, eh? Have you always used that RDBMS? If not, what made you abandon MySQL?

It looks like you are restarting the DB service every time you toggle logging. Is there a way to do that without a restart?

MySQL 5.1 allows you to toggle logging during runtime. But for earlier versions, doesn't look like it.

Abhishek Reddy's picture

He has: 3,348 posts

Joined: Jul 2001

teammatt3 wrote:
It looks like you are restarting the DB service every time you toggle logging. Is there a way to do that without a restart?

Good point. I see no reason why the logging configuration settings cannot be updated at runtime.

You ought to be able to drop into psql as the postgres superuser and do something like this:

# sudo -u postgres psql
postgres=# set log_min_messages to DEBUG2;

Am I missing something, Jeeves?

JeevesBond's picture

He has: 3,955 posts

Joined: Jun 2002

Am I missing something, Jeeves?

Nope, that's a really good idea actually. Smiling

I've only ever used psql for creating users, databases and fiddling with permissions. It never even occured to me that I could change the logging settings at runtime!

My methodology was to vim /etc/init.d/postgresql-8.3, see what the init script was using to control the service, then do man pg_cluster. After a bit of rooting around in man files I found the startup options for debugging.

So, as you can see, I was assuming I'd have to restart the daemon to get debugging. Smiling

a Padded Cell our articles site!

Abhishek Reddy's picture

He has: 3,348 posts

Joined: Jul 2001

JeevesBond wrote:
My methodology was to vim /etc/init.d/postgresql-8.3, see what the init script was using to control the service, then do man pg_cluster. After a bit of rooting around in man files I found the startup options for debugging.

Fair enough. Rather new to Postgres myself, and I had resorted to restarting the service whilst updating postgresql.conf, when I had to deploy it for the first time in anger. Have been getting used to psql since then, however. Smiling

Interesting thread, thanks for posting it.

JeevesBond's picture

He has: 3,955 posts

Joined: Jun 2002

Have you always used that RDBMS? If not, what made you abandon MySQL?

I haven't really abandoned MySQL, but I do think of it as being a little like the Internet Explorer of the RDBMS world. Smiling

I use Postgres mostly for Drupal development, both because the community needs testing using it and due to its closer adherence to the SQL standards. Closer adherence to the standards means I write better -- or at least more portable -- code.

MySQL 5.1 allows you to toggle logging during runtime.

That's interesting, I was trying to get this working using mysqladmin without much luck. Think it may have been pesky Apparmour disallowing MySQL access to a log file. I'll try it again.

*** EDIT ***
Seems 5.1 is when general_log was introduced. Am on 5.0.75 here, that's why it doesn't work.

There's the log variable, but that's read-only at runtime. So, to clarify are you MySQL 5.1+ people doing the following to turn on logging?

mysql -uroot -p
SET general_log = ON;

a Padded Cell our articles site!

JeevesBond's picture

He has: 3,955 posts

Joined: Jun 2002

Instructions for MySQL:

Copy and paste the following to the command line:

sudo /etc/init.d/mysql stop

Then:

sudo mysqld --log=/var/log/mysql.log &

Will start up a copy of MySQL that logs all queries to the /var/log/mysql.log file.

Now, to view the queries as they're being run, copy and paste this to the command line:

tail -f /var/log/mysql.log

a Padded Cell our articles site!

Greg K's picture

He has: 2,145 posts

Joined: Nov 2003

Well, the spam - "let me get my link listed post" was actually useful. I missed this thread when it was active. (for regular users, the post has been unpublished)

I am going to look around to see if there is a way to do this run time as well for mySQL as that would be nice. With our new CMS we launched at the beginning of the year, we are doing pretty much all PDO, called from within data classes, and being able to check the actual query would be nice. However full time logging with 20+ active cevelopment sites would fill the logs quickly.

Thanks for the tips Jeeves!

-Greg

They have: 3 posts

Joined: Jul 2009

Testing and debugging SQL database-methods. After an SQL Database Method has been created.

They have: 2 posts

Joined: Aug 2009

A lot of useful information in this post, thanks. I feel that it might even be too much for me to “digest” .

They have: 3 posts

Joined: Jul 2009

I needed a quick way to debug what PDO statements were being executed (and their parameters) by Drupal 7's DBTNG. I could have used the devel module, ...

They have: 1 posts

Joined: Jun 2010

It looks like you are restarting the DB service every time you toggle logging. Is there a way to do that without a restart?

Want to join the discussion? Create an account or log in if you already have one. Joining is fast, free and painless! We’ll even whisk you back here when you’ve finished.