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

    • 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

      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.

            brendanheywood Brendan Heywood
            brendanheywood Brendan Heywood
            Tim Hunt Tim Hunt
            Jun Pataleta Jun Pataleta
            Janelle Barcega Janelle Barcega
            Votes:
            6 Vote for this issue
            Watchers:
            22 Start watching this issue

              Created:
              Updated:
              Resolved:

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

                  Error rendering 'clockify-timesheets-time-tracking-reports:timer-sidebar'. Please contact your Jira administrators.