query elapsed time

[Conrad Leonard]

There is a minor issue with the elapsed time for queries that is shown in logs and the CLI "stardog-admin query list" command; it looks like the calculation is done by using the time supplied from the client request as the start time, and the time supplied from the server as the end time. If these are out of sync this gives misleading results:

client ahead of server (query appears to have been running for 21 minutes even though it's just started)

[conradL@qimr13054 ~]$ date && ssh $serverip "date"

Thu Aug 20 11:30:04 AEST 2015

Thu Aug 20 11:08:51 AEST 2015

[conradL@qimr13054 ~]$ bash -c "stardog query http://$serverip:5820/grafli longRunningQuery.sparql &" && sleep 1; stardog-admin --server http://$serverip:5820 query 

+----------+----------+---------------+--------------+--------------+

| Query ID | Database |     User      | Elapsed time |   Timeout    |

+----------+----------+---------------+--------------+--------------+

| 13962    | grafli   | stardog-admin | 00:21:14.562 | 00:05:00.000 |

+----------+----------+---------------+--------------+--------------+

server ahead of client: 

[conradL@qimr13054 ~]$ date && ssh $serverip "date"

Thu Aug 20 10:58:38 AEST 2015

Thu Aug 20 11:02:52 AEST 2015

[conradL@qimr13054 ~]$ bash -c "stardog query http://$serverip:5820/grafli longRunningQuery.sparql &" && sleep 1; stardog-admin --server http://$serverip:5820 query list

+----------+----------+---------------+----------------+--------------+

| Query ID | Database |     User      |  Elapsed time  |   Timeout    |

+----------+----------+---------------+----------------+--------------+

| 13961    | grafli   | stardog-admin | 00:-4:-12.-877 | 00:05:00.000 |

+----------+----------+---------------+----------------+--------------+

Similar results are seen in the logs, where the logged elapsed time always contains a fixed offset of +(client-server) seconds. The correct (safe) calculation should always only involve server times. 

These are contrived examples, but one can easily imagine cases where server and client don't have access to the same timeserver and are out by seconds, or one does not have TZ set and are out by hours, or other cases, and the offsets become an issue when using logs to identify performance issues.

Incidentally the fact that the first case shows an elapsed time of 21 minutes but Timeout is set to 5 minutes and the query is still running leads me to believe that the Timeout at least must be using only server times?

[Evren Sirin]

Query start time is always the server time and timeouts use server time to check elapsed time. You are right that the cli command (and the webconsole) use the client time to report elapsed time which could be out of sync with the server. But the logs at the server should always be accurate. In which log do you see incorrect times?

Best,

Evren

--
-- --
You received this message because you are subscribed to the C&P "Stardog" group.
To post to this group, send email to sta...@clarkparsia.com
To unsubscribe from this group, send email to
stardog+u...@clarkparsia.com
For more options, visit this group at
http://groups.google.com/a/clarkparsia.com/group/stardog?hl=en

[Conrad Leonard]

huh, so this was my misunderstanding of the logs. They're not out of sync, and in fact now I understand the access.log doesn't actually contain any information about query running time. What was happening was this:

I export the access.log from the server to a client machine, read it using ProtoBufLogReader, in particular looking at the executionTime property of the DefaultQueryInfo, and was seeing a minimum value for executionTime of the offset between client and server. 

What I hadn't noticed is that the access.log entries are created at query start time; the endTime property is always -1, and getExecutionTime() must be returning (now() - startTime()) if endTime is -1. So in fact the "executionTime" value I read in access.log is always whatever time it is right now on whatever machine is reading the logs, minus the query start time.

Having discovered this, is there an out-of-the-box method to track query running times? Does audit-level logging record query end time?

[Evren Sirin]

On Thu, Aug 20, 2015 at 11:36 PM, Conrad Leonard
<conrad....@hotmail.com> wrote:
> huh, so this was my misunderstanding of the logs. They're not out of sync,
> and in fact now I understand the access.log doesn't actually contain any
> information about query running time.

Correct. Access log only contains an entry for query start events.

> What was happening was this:
>
> I export the access.log from the server to a client machine, read it using
> ProtoBufLogReader, in particular looking at the executionTime property of
> the DefaultQueryInfo, and was seeing a minimum value for executionTime of
> the offset between client and server.
>
> What I hadn't noticed is that the access.log entries are created at query
> start time; the endTime property is always -1, and getExecutionTime() must
> be returning (now() - startTime()) if endTime is -1. So in fact the
> "executionTime" value I read in access.log is always whatever time it is
> right now on whatever machine is reading the logs, minus the query start
> time.

Yes, that's how `getExecutionTime()` behaves [1] and where the issue
with out of sync clocks occurs.

>
> Having discovered this, is there an out-of-the-box method to track query
> running times? Does audit-level logging record query end time?

Yes, audit log will include query end events too which will have the
end time set by the server so the execution time will be correct. The
other possibility is to use the slow query log. This log looks at only
query end events and if you set `logging.slow_query.time = 0s` then
you'll get all query execution times in the log. By default, slow
query log uses a special human-readable format but you can use the
protobuf text or binary formats too.

Best,
Evren


[1] http://docs.stardog.com/java/snarl/com/complexible/stardog/QueryInfo.html#getExecutionTime()

[Conrad Leonard]

Thanks Evren, I will enable the slow query log as you suggest.