0

We are observing inconsistency between a number of concurrent queries as reported by StackDriver and what we see in "data_access" log and a number reported my "Query" metric.

As it can be seen from the image attached at around 1:16pm there was a spike of concurrent queries to 87 (not sure if that is even possible since there is a concurrent queries quota of 50) and if we count jobCompletedEvent from "data_access" log with createTimeTIMESTAMP("2017-01-19 13:16:48","America/Los_Angeles") we can only see 24.

This instance is not an isolated, and we have many of these happening.

enter image description here

SELECT
  count(*)
FROM (
  SELECT
    createTime,
    startTime,
    endTime
  FROM (
    SELECT
      protoPayload.serviceData.jobCompletedEvent.job.jobStatistics.createTime AS createTime,
      protoPayload.serviceData.jobCompletedEvent.job.jobStatistics.startTime AS startTime,
      protoPayload.serviceData.jobCompletedEvent.job.jobStatistics.endTime AS endTime
    FROM
      `catalog.cloudaudit_googleapis_com_data_access_201701*`))
WHERE
  createTime<TIMESTAMP("2017-01-19 13:16:48","America/Los_Angeles")
  AND endTime>TIMESTAMP("2017-01-19 13:16:48","America/Los_Angeles")

Investigating it a bit further it got a bit strange. Here is the query if I look at jobGetQueryResultsResponse stats

    SELECT
    insertId,
    jobId,
    createTime,
    startTime,
    endTime
FROM (
  SELECT
    insertId,
    jobId,
    createTime,
    startTime,
    endTime
  FROM (
    SELECT
      insertId,
      protoPayload.serviceData.jobGetQueryResultsResponse.job.jobName.jobId AS jobId,
      protoPayload.serviceData.jobGetQueryResultsResponse.job.jobStatistics.createTime AS createTime,
      protoPayload.serviceData.jobGetQueryResultsResponse.job.jobStatistics.startTime AS startTime,
      protoPayload.serviceData.jobGetQueryResultsResponse.job.jobStatistics.endTime AS endTime,
      protoPayload.status.message error
    FROM
      `catalog.cloudaudit_googleapis_com_data_access_201701*`))
WHERE
  createTime<=TIMESTAMP("2017-01-19 13:16:48")
  AND endTime>=TIMESTAMP("2017-01-19 13:16:48")

it now returns 321 records (snippet below) where there are many duplicates with unique insertID but the same jobId

116 5467305DA3861.A4954C2.780CB7F5  job__oFOLJVnNr8Xj7zFnNrgqww6_Ww 2017-01-19 13:16:35 UTC 2017-01-19 13:16:36 UTC 2017-01-19 13:16:53 UTC  
117 54672C24D1181.A036F52.D205C885  bqjob_r31c3135d053792f3_00000159b6d384e3_1  2017-01-19 13:03:52 UTC 2017-01-19 13:03:55 UTC 2017-01-19 13:46:09 UTC  
118 54672C333EB29.A498C8D.1E00E7D1  job__oFOLJVnNr8Xj7zFnNrgqww6_Ww 2017-01-19 13:16:35 UTC 2017-01-19 13:16:36 UTC 2017-01-19 13:16:53 UTC  
119 5467285CC92D1.A496505.560166F3  job__oFOLJVnNr8Xj7zFnNrgqww6_Ww 2017-01-19 13:16:35 UTC 2017-01-19 13:16:36 UTC 2017-01-19 13:16:53 UTC  
120 5467355C301E1.A49D803.540CE70C  job__oFOLJVnNr8Xj7zFnNrgqww6_Ww 2017-01-19 13:16:35 UTC 2017-01-19 13:16:36 UTC 2017-01-19 13:16:53 UTC  
121 54673441FDAF9.A49C44D.82036D2F  job__oFOLJVnNr8Xj7zFnNrgqww6_Ww 2017-01-19 13:16:35 UTC 2017-01-19 13:16:36 UTC 2017-01-19 13:16:53 UTC 

Could this trigger an inconsistency and what is the quota implications. Could you please clarify how "Query Count" metric is being calculated. How reliable BigQuery StackDriver logs are and what is the best way to get accurate count from "data_access" log.

0 Answers0