Need a way to record CQ execution time

[beckettsean]

Feature Request

Proposal: [Description of the feature]

Log entries for CQs should give execution time

Current behavior: [What currently happens]

For ad hoc API queries, first we log the [query] statement and then the [httpd] response, which gives the elapsed time for the request, and thus for the query:

[query] 2016/06/24 16:54:30 SHOW QUERIES
[httpd] 2016/06/24 16:54:30 127.0.0.1 - - [24/Jun/2016:16:54:30 -0400] POST /query?chunked=true&db=telegraf&q=show+queries HTTP/1.1 200 142 - InfluxDBShell/0.13.0 d8fbeb8b-3a4d-11e6-8b22-000000000000 2.985797ms

Continuous queries log the [query] entry, but since they don't pass through the HTTP API, the [continuous querier] output doesn't log any execution time.

[query] 2016/06/24 16:54:20 SELECT max(usage_user) AS m_u_u, max(usage_system) AS m_u_s INTO telegraf.forever.test FROM telegraf."default".cpu WHERE time >= '2016-06-24T19:50:30Z' AND time < '2016-06-24T19:50:40Z' GROUP BY time(10s), *
[continuous_querier] 2016/06/24 16:54:20 executing continuous query foo (2016-06-24 15:50:20 -0400 EDT to 2016-06-24 15:50:30 -0400 EDT)

Desired behavior: [What you would like to happen]

The [continuous querier] line should include the query execution time.

Use case: [Why is this important (helps with prioritizing requests)]

There's no way to determine the performance of particular CQ queries within the system itself, nor is there any historical record to which to compare. Either CQs should log execution times or they should write them into _internal somewhere (could get very chatty there, logs seem better to me).

[jsternberg]

The code for this is done, but I'm throwing this into the 1.1 milestone as I don't think this is urgent enough that this needs to go into 1.0 since we want to keep the number of changes before 1.0 to a minimum.

@beckettsean if you think this should go into 1.0, please comment so that we can potentially change the milestone. Thanks.

[beckettsean]

1.1 is fine. It will just make schema consults more challenging until then.

[beckettsean]

For posterity abd because I was curious, the slow query log does catch continuous queries but it doesn't record execution time:

[query] 2016/07/05 14:52:17 Detected slow query: SELECT max(usage_user) AS m_u_u, max(usage_system) AS m_u_s INTO telegraf.forever.test FROM telegraf."default".cpu WHERE time >= '2016-07-05T18:35:30Z' AND time < '2016-07-05T18:35:40Z' GROUP BY time(10s), * (qid: 101, database: telegraf, threshold: 10ms)

[jsternberg]

Looks like @jwilder OK'd the PR for this to go into 1.0.0 so I'm going to update the milestone.

[MikeSchroll]

For extremely long-running CQs (a problem)
Does this create a situation where its no longer possible to diagnose that simply by referencing the log file to see that its running; because it will only show in the log once its complete, and has an execution time to display?

And for everyone's reference, what would be the proper way to troubleshoot such a problem without the 'real-time' log reference?

[jwilder]

@MikeSchroll SHOW QUERIES will show running queries and their current runtime in realtime.