Details
-
Type:
Bug
-
Status: Done
-
Resolution: Done
-
Fix Version/s: None
-
Component/s: Qserv
-
Labels:
-
Story Points:4
-
Epic Link:
-
Sprint:DB_F16_10, DB_S17_12, DB_S17_01
-
Team:Data Access and Database
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
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 |
|
+---------+-------+--------+-----------+----------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+--------------+-----------+---------------------+---------------------+----------+
|
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.
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;
|
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;
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)
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) John, looks OK, see my comments on PR. Igor, please mark ticket as reviewed when you are done.
To the best of my knowledge changes look good to me.
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:
total 4020164drwxr-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.logdrwxr-xr-x 2 qserv qserv 8192 Nov 8 00:00 worker-rw-r--r-- 1 qserv qserv 0 Oct 11 02:37 xrootd-console.logThe query in question and its timing was found by parsing the log file of the MySQL proxy service:
....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
493Then all records containing this identifier were pulled from the log file:
Further analysis of that file allowed to get the boundaries of the query:
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:
...QuerySession description:has chunks: 1chunks: []needs merge: 1lterId=1merge statement: SELECT SUM(QS1_COUNT)scanRating:15 ScanTable: sdss_stripe82_00.Science_Ccd_Exposure lock=0 rating=0ScanTable: sdss_stripe82_00.RunDeepForcedSource lock=1 rating=15...