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

Have an optional sql debug mode which instruments sql with the calling php code

    XMLWordPrintable

    Details

    • Testing Instructions:
      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
    • Affected Branches:
      MOODLE_39_STABLE
    • Fixed Branches:
      MOODLE_310_STABLE
    • Pull Master Branch:
      MDL-68874-db-sql-instrumentation

      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

              Assignee:
              brendanheywood Brendan Heywood
              Reporter:
              brendanheywood Brendan Heywood
              Peer reviewer:
              Tim Hunt
              Integrator:
              Jun Pataleta
              Tester:
              Janelle Barcega
              Participants:
              Component watchers:
              Andrew Nicols, Jun Pataleta, Michael Hawkins, Shamim Rezaie, Simey Lameze
              Votes:
              6 Vote for this issue
              Watchers:
              17 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Fix Release Date:
                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