Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-68874

Debug option to instrument SQL queries with the PHP code line/stack-trace for better logging

    XMLWordPrintable

Details

    • MOODLE_39_STABLE
    • MOODLE_310_STABLE
    • MDL-68874-db-sql-instrumentation
    • Hide

      Example using Postgres slow log

      1) Edit Postgres config and turn on full statement debugging (eg /etc/postgresql/10/main/postgresql.conf)

      log_min_duration_statement = 0

      2) restart postgres

      sudo service postgresql restart

      3) tail the postgres logs

      tail -f /var/log/postgresql/postgresql-10-main.log

      4) do anything on the site, confirm you see raw sql

      5) Visit debugging page and set debugsqltrace to 1

      /admin/settings.php?section=debugging

      6) Confirm you can see 1 line of the code that called the dml function

      7) Rinse and repeat with setting to 2 lines and all lines

      8) confirm in the sql that you can see the exact line and line number of the php code which calls the DB method:

      2020-06-02 17:11:49.340 AEST [15386] moodlelocal@moodlelocal LOG:  duration: 0.538 ms  execute <unnamed>: DECLARE crs1 NO SCROLL CURSOR WITH HOLD FOR SELECT f.filter, fc.name, fc.value
      	              FROM mdl_filter_active f
      	         LEFT JOIN mdl_filter_config fc
      	                ON fc.filter = f.filter
      	               AND fc.contextid = f.contextid
      	             WHERE f.contextid = $1
      	               AND f.active != $2
      	          ORDER BY f.sortorder
      	-- line 801 of /lib/filterlib.php: call to pgsql_native_moodle_database->get_recordset_sql()
      	-- line 281 of /lib/filterlib.php: call to filter_get_globally_enabled_filters_with_config()
      

      Rinse and repeat for other DBs as needed

      Show
      Example using Postgres slow log 1) Edit Postgres config and turn on full statement debugging (eg /etc/postgresql/10/main/postgresql.conf) log_min_duration_statement = 0 2) restart postgres sudo service postgresql restart 3) tail the postgres logs tail -f /var/log/postgresql/postgresql-10-main.log 4) do anything on the site, confirm you see raw sql 5) Visit debugging page and set debugsqltrace to 1 /admin/settings.php?section=debugging 6) Confirm you can see 1 line of the code that called the dml function 7) Rinse and repeat with setting to 2 lines and all lines 8) confirm in the sql that you can see the exact line and line number of the php code which calls the DB method: 2020-06-02 17:11:49.340 AEST [15386] moodlelocal@moodlelocal LOG: duration: 0.538 ms execute <unnamed>: DECLARE crs1 NO SCROLL CURSOR WITH HOLD FOR SELECT f.filter, fc.name, fc.value FROM mdl_filter_active f LEFT JOIN mdl_filter_config fc ON fc.filter = f.filter AND fc.contextid = f.contextid WHERE f.contextid = $1 AND f.active != $2 ORDER BY f.sortorder -- line 801 of /lib/filterlib.php: call to pgsql_native_moodle_database->get_recordset_sql() -- line 281 of /lib/filterlib.php: call to filter_get_globally_enabled_filters_with_config() Rinse and repeat for other DBs as needed

    Description

      Sysadmin: I have some sql: xyz, what code is calling this?

      Dev: ummm

      This happens a lot, the more complicated sql is often constructed from lots of smaller clauses concatenated together so a simple search never works.

      Proposing a simple debug mode which when on adds in some extra comment.

      Attachments

        Issue Links

          Activity

            People

              brendanheywood Brendan Heywood
              brendanheywood Brendan Heywood
              Tim Hunt Tim Hunt
              Jun Pataleta Jun Pataleta
              Janelle Barcega Janelle Barcega
              David Woloszyn, Huong Nguyen, Jake Dallimore, Meirza, Michael Hawkins, Raquel Ortega, Safat Shahin, Stevani Andolo
              Votes:
              6 Vote for this issue
              Watchers:
              22 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:
                9/Nov/20

                Time Tracking

                  Estimated:
                  Original Estimate - 0 minutes
                  0m
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 1 day, 4 hours, 20 minutes
                  1d 4h 20m