Uploaded image for project: 'Data Management'
  1. Data Management
  2. DM-8226

PDAC: query restricted by objectId is not using secondary index

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Done
    • Resolution: Done
    • Fix Version/s: None
    • Component/s: Qserv
    • Labels:

      Description

      In the PDAC, the following query is broadcast to all workers:

      select count(*) from Science_Ccd_Exposure,RunDeepForcedSource
        where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1;
      

      Shouldn't this use the secondary index and be directed to just the worker holding the chunk for the specified objectId?

        Attachments

          Activity

          Hide
          gapon Igor Gaponenko added a comment - - edited

          Analyzing the query processing by Czar (log files)

          In a specific deployment of Qserv in PDAC the master log files are located on node lsst-qserv-master01 at:

          % sudo ls -al /qserv/log
          total 4020164
          drwxr-xr-x 3 qserv qserv        154 Nov  7 12:13 .
          drwxrwx--- 4 qserv qserv         27 Nov  3 15:28 ..
          -rw-r----- 1 qserv qserv      76187 Nov  7 12:17 mysqld.log
          -rw-r----- 1 qserv qserv      17627 Nov  8 19:53 mysql-proxy.log
          -rw-r--r-- 1 qserv qserv 4109190215 Nov  8 20:17 mysql-proxy-lua.log
          -rw-r--r-- 1 qserv qserv       4092 Nov  4 15:49 qserv-watcher.log
          -rw-r--r-- 1 qserv qserv    7331575 Nov  7 12:17 qserv-wmgr.log
          drwxr-xr-x 2 qserv qserv       8192 Nov  8 00:00 worker
          -rw-r--r-- 1 qserv qserv          0 Oct 11 02:37 xrootd-console.log
          

          The query in question and its timing was found by parsing the log file of the MySQL proxy service:

          sudo cat /qserv/log/mysql-proxy-lua.log | \
            grep 'UserQuery registered' | \
            awk -F\[ '{print $2" "$3}' | \
            awk -F\] '{print $1": "$3}' | \
            awk -F\: '{print $1":"$2":"$3" "$6}' | \
            sed -e 's/ UserQuery registered //'
          ..
          2016-11-08T18:14:59.902-0600 select count(*) from Science_Ccd_Exposure,RunDeepForcedSource where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1;
          ..
          

          The next step was to find the Query ID corresponding to that query by parsing the log file in the vicinity of the query. The identifier was

          493
          

          Then all records containing this identifier were pulled from the log file:

          sudo fgrep 'QI=493' /qserv/log/mysql-proxy-lua.log > temp/QI_493.log
          

          Further analysis of that file allowed to get the boundaries of the query:

          head -1 temp/QI_493.log
          [2016-11-08T19:18:50.724-0600] [LWP:1702] DEBUG qmeta.QMetaMysql (core/modules/qmeta/QMetaMysql.cc:300) - QI=493: Executing query: INSERT INTO QTable (queryId, dbName, tblName) VALUES (493, 'sdss_stripe82_00', 'Science_Ccd_Exposure')
           
          tail -1 temp/QI_493.log
          [2016-11-08T19:18:55.070-0600] [LWP:4195] DEBUG ccontrol.UserQuerySelect (core/modules/ccontrol/UserQuerySelect.cc:293) - QI=493: Discarded UserQuerySelect
          

          And am ultimate reason for this particular bug report was found in the same log file. According to the log file Master broadcast this query to all 1080 chunks. There are 1080 query sub-ID*s reported in the log, and for each such *sub-ID there is a dedicated instance of the QueryRequest object instantiated at the begining and discarded in the end. For example:

          ...
          [2016-11-08T19:18:54.455-0600] [LWP:4080] DEBUG root (core/modules/qdisp/QueryRequest.cc:287) - QI=493:1079; QueryRequest::cleanup()
          [2016-11-08T19:18:54.577-0600] [LWP:4195] DEBUG ccontrol.UserQuerySelect (core/modules/ccontrol/UserQuerySelect.cc:254) - QI=493: Joined everything (success)
          [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.JobQuery (core/modules/qdisp/JobQuery.cc:60) - ~JobQuery QI=493:1079;
          [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.QueryRequest (core/modules/qdisp/QueryRequest.cc:66) - QI=493:1079; ~QueryRequest
          [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.JobQuery (core/modules/qdisp/JobQuery.cc:60) - ~JobQuery QI=493:1078;
          [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.QueryRequest (core/modules/qdisp/QueryRequest.cc:66) - QI=493:1078; ~QueryRequest
          [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.JobQuery (core/modules/qdisp/JobQuery.cc:60) - ~JobQuery QI=493:1077;
          [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.QueryRequest (core/modules/qdisp/QueryRequest.cc:66) - QI=493:1077; ~QueryRequest
          [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.JobQuery (core/modules/qdisp/JobQuery.cc:60) - ~JobQuery QI=493:1076;
          ...
          

          More over, there is a direct evidence that this query is supposed to be "chunked*. This is seen in the log file analysis:

          %  sudo fgrep 'QI=493' -B 100 /qserv/log/mysql-proxy-lua.log
          ...
          [2016-11-08T19:18:50.720-0600] [LWP:1702] DEBUG qproc.QuerySession (core/modules/qproc/QuerySession.cc:108) - Query Plugins applied:
           QuerySession description:
            original: select count(*) from Science_Ccd_Exposure,RunDeepForcedSource where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1;
            has chunks: 1
            chunks: []
            needs merge: 1
            1st parallel statement: SELECT count(*) AS QS1_COUNT FROM sdss_stripe82_00.Science_Ccd_Exposure AS QST_1_,sdss_stripe82_00.RunDeepForcedSource_%CC% AS QST_2_ WHERE scienceCcdExposureId=exposure_id AND objectId=3219370448785419 AND fi
          lterId=1
            merge statement: SELECT SUM(QS1_COUNT)
            scanRating:15  ScanTable: sdss_stripe82_00.Science_Ccd_Exposure lock=0 rating=0
            ScanTable: sdss_stripe82_00.RunDeepForcedSource lock=1 rating=15
          ...
          

          Show
          gapon Igor Gaponenko added a comment - - edited Analyzing the query processing by Czar (log files) In a specific deployment of Qserv in PDAC the master log files are located on node lsst-qserv-master01 at: % sudo ls -al /qserv/log total 4020164 drwxr-xr-x 3 qserv qserv 154 Nov 7 12:13 . drwxrwx--- 4 qserv qserv 27 Nov 3 15:28 .. -rw-r----- 1 qserv qserv 76187 Nov 7 12:17 mysqld.log -rw-r----- 1 qserv qserv 17627 Nov 8 19:53 mysql-proxy.log -rw-r--r-- 1 qserv qserv 4109190215 Nov 8 20:17 mysql-proxy-lua.log -rw-r--r-- 1 qserv qserv 4092 Nov 4 15:49 qserv-watcher.log -rw-r--r-- 1 qserv qserv 7331575 Nov 7 12:17 qserv-wmgr.log drwxr-xr-x 2 qserv qserv 8192 Nov 8 00:00 worker -rw-r--r-- 1 qserv qserv 0 Oct 11 02:37 xrootd-console.log The query in question and its timing was found by parsing the log file of the MySQL proxy service: sudo cat /qserv/log/mysql-proxy-lua .log | \ grep 'UserQuery registered' | \ awk -F\[ '{print $2" "$3}' | \ awk -F\] '{print $1": "$3}' | \ awk -F\: '{print $1":"$2":"$3" "$6}' | \ sed -e 's/ UserQuery registered //' .. 2016-11-08T18:14:59.902-0600 select count(*) from Science_Ccd_Exposure,RunDeepForcedSource where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1; .. The next step was to find the Query ID corresponding to that query by parsing the log file in the vicinity of the query. The identifier was 493 Then all records containing this identifier were pulled from the log file: sudo fgrep 'QI=493' /qserv/log/mysql-proxy-lua .log > temp /QI_493 .log Further analysis of that file allowed to get the boundaries of the query: head -1 temp /QI_493 .log [2016-11-08T19:18:50.724-0600] [LWP:1702] DEBUG qmeta.QMetaMysql (core /modules/qmeta/QMetaMysql .cc:300) - QI=493: Executing query: INSERT INTO QTable (queryId, dbName, tblName) VALUES (493, 'sdss_stripe82_00' , 'Science_Ccd_Exposure' )   tail -1 temp /QI_493 .log [2016-11-08T19:18:55.070-0600] [LWP:4195] DEBUG ccontrol.UserQuerySelect (core /modules/ccontrol/UserQuerySelect .cc:293) - QI=493: Discarded UserQuerySelect And am ultimate reason for this particular bug report was found in the same log file. According to the log file Master broadcast this query to all 1080 chunks. There are 1080 query sub-ID*s reported in the log, and for each such *sub-ID there is a dedicated instance of the QueryRequest object instantiated at the begining and discarded in the end. For example: ... [2016-11-08T19:18:54.455-0600] [LWP:4080] DEBUG root (core/modules/qdisp/QueryRequest.cc:287) - QI=493:1079; QueryRequest::cleanup() [2016-11-08T19:18:54.577-0600] [LWP:4195] DEBUG ccontrol.UserQuerySelect (core/modules/ccontrol/UserQuerySelect.cc:254) - QI=493: Joined everything (success) [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.JobQuery (core/modules/qdisp/JobQuery.cc:60) - ~JobQuery QI=493:1079; [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.QueryRequest (core/modules/qdisp/QueryRequest.cc:66) - QI=493:1079; ~QueryRequest [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.JobQuery (core/modules/qdisp/JobQuery.cc:60) - ~JobQuery QI=493:1078; [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.QueryRequest (core/modules/qdisp/QueryRequest.cc:66) - QI=493:1078; ~QueryRequest [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.JobQuery (core/modules/qdisp/JobQuery.cc:60) - ~JobQuery QI=493:1077; [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.QueryRequest (core/modules/qdisp/QueryRequest.cc:66) - QI=493:1077; ~QueryRequest [2016-11-08T19:18:54.828-0600] [LWP:4195] DEBUG qdisp.JobQuery (core/modules/qdisp/JobQuery.cc:60) - ~JobQuery QI=493:1076; ... More over, there is a direct evidence that this query is supposed to be "chunked*. This is seen in the log file analysis: % sudo fgrep 'QI=493' -B 100 /qserv/log/mysql-proxy-lua .log ... [2016-11-08T19:18:50.720-0600] [LWP:1702] DEBUG qproc.QuerySession (core /modules/qproc/QuerySession .cc:108) - Query Plugins applied: QuerySession description: original: select count(*) from Science_Ccd_Exposure,RunDeepForcedSource where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1; has chunks: 1 chunks: [] needs merge: 1 1st parallel statement: SELECT count(*) AS QS1_COUNT FROM sdss_stripe82_00.Science_Ccd_Exposure AS QST_1_,sdss_stripe82_00.RunDeepForcedSource_%CC% AS QST_2_ WHERE scienceCcdExposureId=exposure_id AND objectId=3219370448785419 AND fi lterId=1 merge statement: SELECT SUM(QS1_COUNT) scanRating:15 ScanTable: sdss_stripe82_00.Science_Ccd_Exposure lock=0 rating=0 ScanTable: sdss_stripe82_00.RunDeepForcedSource lock=1 rating=15 ...
          Hide
          gapon Igor Gaponenko added a comment -

          Analyzing the query status within qservMeta database of CZAR

          Another possibility to get more information on queries is by looking at tables at a special database qservMeta of czar:

          USE qservMeta;
          SHOW TABLES;
          

          +---------------------------------------+
          | Tables_in_qservMeta                   |
          +---------------------------------------+
          | QCzar                                 |
          | QInfo                                 |
          | QTable                                |
          | QWorker                               |
          | qservTest_case01_qserv__Object        |
          | qservTest_case02_qserv__Object        |
          | qservTest_case03_qserv__RunDeepSource |
          | qservTest_case04_qserv__DeepSource    |
          | qservTest_case05_qserv__Object        |
          | sdss_stripe82_00__RunDeepSource       |
          +---------------------------------------+
          

          SELECT * FROM QTable WHERE queryId=493;
          

          +---------+------------------+----------------------+
          | queryId | dbName           | tblName              |
          +---------+------------------+----------------------+
          |     493 | sdss_stripe82_00 | RunDeepForcedSource  |
          |     493 | sdss_stripe82_00 | Science_Ccd_Exposure |
          +---------+------------------+----------------------+
          

          SELECT * FROM QInfo WHERE queryId=493;
          

          +---------+-------+--------+-----------+----------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--------------+-----------+---------------------+---------------------+----------+
          | queryId | qType | czarId | user      | query                                                                                                                                              | qTemplate                                                                                                                                                                                                                 | qMerge                | proxyOrderBy | status    | submitted           | completed           | returned |
          +---------+-------+--------+-----------+----------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--------------+-----------+---------------------+---------------------+----------+
          |     493 | SYNC  |      2 | anonymous | select count(*) from Science_Ccd_Exposure,RunDeepForcedSource where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1; | SELECT count(*) AS QS1_COUNT FROM sdss_stripe82_00.Science_Ccd_Exposure AS QST_1_,sdss_stripe82_00.RunDeepForcedSource_%CC% AS QST_2_ WHERE scienceCcdExposureId=exposure_id AND objectId=3219370448785419 AND filterId=1 | SELECT SUM(QS1_COUNT) | NULL         | COMPLETED | 2016-11-08 19:18:50 | 2016-11-08 19:18:54 | NULL     |
          +---------+-------+--------+-----------+----------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--------------+-----------+---------------------+---------------------+----------+
          

          Show
          gapon Igor Gaponenko added a comment - Analyzing the query status within qservMeta database of CZAR Another possibility to get more information on queries is by looking at tables at a special database qservMeta of czar : USE qservMeta; SHOW TABLES; +---------------------------------------+ | Tables_in_qservMeta | +---------------------------------------+ | QCzar | | QInfo | | QTable | | QWorker | | qservTest_case01_qserv__Object | | qservTest_case02_qserv__Object | | qservTest_case03_qserv__RunDeepSource | | qservTest_case04_qserv__DeepSource | | qservTest_case05_qserv__Object | | sdss_stripe82_00__RunDeepSource | +---------------------------------------+ SELECT * FROM QTable WHERE queryId=493; +---------+------------------+----------------------+ | queryId | dbName | tblName | +---------+------------------+----------------------+ | 493 | sdss_stripe82_00 | RunDeepForcedSource | | 493 | sdss_stripe82_00 | Science_Ccd_Exposure | +---------+------------------+----------------------+ SELECT * FROM QInfo WHERE queryId=493; +---------+-------+--------+-----------+----------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--------------+-----------+---------------------+---------------------+----------+ | queryId | qType | czarId | user | query | qTemplate | qMerge | proxyOrderBy | status | submitted | completed | returned | +---------+-------+--------+-----------+----------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--------------+-----------+---------------------+---------------------+----------+ | 493 | SYNC | 2 | anonymous | select count(*) from Science_Ccd_Exposure,RunDeepForcedSource where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1; | SELECT count(*) AS QS1_COUNT FROM sdss_stripe82_00.Science_Ccd_Exposure AS QST_1_,sdss_stripe82_00.RunDeepForcedSource_%CC% AS QST_2_ WHERE scienceCcdExposureId=exposure_id AND objectId=3219370448785419 AND filterId=1 | SELECT SUM(QS1_COUNT) | NULL | COMPLETED | 2016-11-08 19:18:50 | 2016-11-08 19:18:54 | NULL | +---------+-------+--------+-----------+----------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--------------+-----------+---------------------+---------------------+----------+
          Hide
          salnikov Andy Salnikov added a comment -

          FYI, tables like qservTest_case01_qserv__Object are secondary index tables, they are not related to other tables in the same database (QCzar, QInfo, etc.), it is just a coincidence that they are stored in the same mysql database.

          Show
          salnikov Andy Salnikov added a comment - FYI, tables like qservTest_case01_qserv__Object are secondary index tables, they are not related to other tables in the same database (QCzar, QInfo, etc.), it is just a coincidence that they are stored in the same mysql database.
          Hide
          jgates John Gates added a comment -

          I've partially figured out what is going wrong.

          select count(*) from Science_Ccd_Exposure,RunDeepForcedSource where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1;
          

          While the czar does not create a Restrictor for objectId=3219370448785419 above, it does create one for the query below. For the query above, it is trying "Science_Ccd_Exposure.objectId" when it should be trying "RunDeepForcedSource.objectId". "Science_Ccd_Exposure.objectId" does not exist.

          select count(*) from RunDeepForcedSource,Science_Ccd_Exposure   where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1;
          

          Show
          jgates John Gates added a comment - I've partially figured out what is going wrong. select count(*) from Science_Ccd_Exposure,RunDeepForcedSource where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1; While the czar does not create a Restrictor for objectId=3219370448785419 above, it does create one for the query below. For the query above, it is trying "Science_Ccd_Exposure.objectId" when it should be trying "RunDeepForcedSource.objectId". "Science_Ccd_Exposure.objectId" does not exist. select count(*) from RunDeepForcedSource,Science_Ccd_Exposure where scienceCcdExposureId=exposure_id and objectId=3219370448785419 and filterId=1;
          Hide
          jgates John Gates added a comment -

          From Serge -
          when I was working on Qserv, that wasn’t available (but maybe it is now?). I had to add something for spatial join rewriting to qana that might help - see `qana/TableInfo.h` (you can make `TableInfo` instances using a `TableInfoPool` and a `QueryContext`, see `qana/TableInfoPool.h`). This doesn’t give you the full schema, but it will tell you whether a table is a child or director (or match) table according to the CSS, and what the name of primary/foreign key column(s) are. (edited)

          [1:24]
          BTW, I think the underlying problem is that Daniel’s implementation of resolving column references (basically, the code starting at https://github.com/lsst/qserv/blob/master/core/modules/query/QueryContext.cc#L45) also didn’t have access to a schema, so it has no choice but to do totally bogus things when presented with an unqualified column name and multiple tables in the FROM clause. (edited)

          Show
          jgates John Gates added a comment - From Serge - when I was working on Qserv, that wasn’t available (but maybe it is now?). I had to add something for spatial join rewriting to qana that might help - see `qana/TableInfo.h` (you can make `TableInfo` instances using a `TableInfoPool` and a `QueryContext`, see `qana/TableInfoPool.h`). This doesn’t give you the full schema, but it will tell you whether a table is a child or director (or match) table according to the CSS, and what the name of primary/foreign key column(s) are. (edited) [1:24] BTW, I think the underlying problem is that Daniel’s implementation of resolving column references (basically, the code starting at https://github.com/lsst/qserv/blob/master/core/modules/query/QueryContext.cc#L45 ) also didn’t have access to a schema, so it has no choice but to do totally bogus things when presented with an unqualified column name and multiple tables in the FROM clause. (edited)
          Hide
          salnikov Andy Salnikov added a comment -

          John, looks OK, see my comments on PR. Igor, please mark ticket as reviewed when you are done.

          Show
          salnikov Andy Salnikov added a comment - John, looks OK, see my comments on PR. Igor, please mark ticket as reviewed when you are done.
          Hide
          gapon Igor Gaponenko added a comment -

          To the best of my knowledge changes look good to me.

          Show
          gapon Igor Gaponenko added a comment - To the best of my knowledge changes look good to me.

            People

            Assignee:
            jgates John Gates
            Reporter:
            fritzm Fritz Mueller
            Reviewers:
            Andy Salnikov, Igor Gaponenko
            Watchers:
            Andy Salnikov, Fritz Mueller, Igor Gaponenko, John Gates, Xiuqin Wu [X] (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: