Uploaded image for project: 'Sakai'
  1. Sakai
  2. SAK-39741

Add request logging to RequestFilter to assist performance and db query analysis

    Details

    • Type: Task
    • Status: CLOSED
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.6.x
    • Fix Version/s: 2.6.x, 2.7.x
    • Component/s: Kernel
    • Labels:
      None

      Description

      The attached patch adds some debug logging to the RequestFilter to assist in the analysis of number of db queries executed per request, and elapsed time per request.

      This would have no effect in production instances where debug logging for RequestFilter is not enabled.

      It can be enabled using

      log.config.count=1
      log.config.1=DEBUG.org.sakaiproject.util.RequestFilter

      Query logging can be enabled using a mysql connection string with the profileSQL parameter, e.g.

      url@javax.sql.BaseDataSource=jdbc:mysql://localhost:3306/sakai?useUnicode=true&characterEncoding=UTF-8&useServerPrepStmts=false&profileSQL=true

      The results in catalina.out will show the request details, db queries executed, and elapsed time, e.g.:

      15:36:22,987 DEBUG RequestFilter.java:578 RequestFilter:578 - http-request: POST http://mocha.cet.uct.ac.za:8080/portal/xlogin

      Thu Nov 27 15:36:23 SAST 2008 INFO: Profiler Event: [QUERY] at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:102) duration: 1 ms, connection-id: 1872, statement-id: 1380, resultset-id: 0, message: insert into SAKAI_SESSION (SESSION_ID, SESSION_SERVER, SESSION_USER, SESSION_IP, SESSION_HOSTNAME, SESSION_USER_AGENT, SESSION_START, SESSION_END, SESSION_ACTIVE) values (x'30643433613665392D323130322D343963612D613537382D383233393162383465326638', x'73616B61692D7472756E6B2D612D31323237373932373435363838', x'61646D696E', x'etc, x'etc', '2008-11-27 15:36:22', '2008-11-27 15:36:22', 1)

      15:36:23,261 DEBUG RequestFilter.java:649 RequestFilter:649 - request timing (ms): 274 for http-request: POST http://mocha.cet.uct.ac.za:8080/portal/xlogin

      For meaningful analysis, this can be run on a test instance of Sakai with a single client, and the resulting catalina.out analysed by a script. Only one request at a time should be sent so that only 1 request thread is active at any one time. Using Firefox as a client, this can be achieved by setting the about:config parameter:

      network.http.max-connections-per-server=1

        Gliffy Diagrams

          Zeplin

            Attachments

              Issue Links

                Activity

                  People

                  Assignee:
                  smarquard Stephen Marquard
                  Reporter:
                  smarquard Stephen Marquard
                  Votes:
                  0 Vote for this issue
                  Watchers:
                  0 Start watching this issue

                    Dates

                    Created:
                    Updated:
                    Resolved:

                      Git Integration