Inconsistent 'executionTime' units in N1QL audit logs

Analytics
1

Hi, I’m trying to understand SQL++ audit logging for Couchbase 7.1. I found this document (SQL++ Auditing | Couchbase Docs) which states that metrics.executionTime is reported in milliseconds however in practice, that does not always appear to to be the case.

For example, I captured the following queries in the audit.log and I see examples of milliseconds, microseconds, as well numbers without any units.

{"description":"A N1QL SELECT statement was executed","id":28672,"isAdHoc":true,"local":{"ip":"127.0.0.1","port":8093},"metrics":{"elapsedTime":"16.854811ms","executionTime":"16.791091ms","resultCount":1,"resultSize":21},"name":"SELECT statement","node":"127.0.0.1:8091","real_userid":{"domain":"local","user":"admin"},"remote":{"ip":"127.0.0.1","port":57957},"requestId":"6eddb4cf-0e6d-404d-9adb-c5c7b60b7568","statement":"select buckets.name from system:buckets;","status":"success","timestamp":"2023-12-07T19:33:28.645Z","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:109.0) Gecko/20100101 Firefox/115.0"}

{"description":"An unrecognized statement was received by the N1QL query engine","id":28687,"isAdHoc":true,"local":{"ip":"xxx","port":8093},"metrics":{"elapsedTime":"956.485µs","errorCount":1,"executionTime":"825.114µs","resultCount":0,"resultSize":0},"name":"UNRECOGNIZED statement","node":"127.0.0.1:8091","real_userid":{"domain":"local","user":"admin"},"remote":{"ip":"xxx","port":38804},"requestId":"00fbbd59-57e8-41e7-b1a6-7fee6de9361a","statement":"select value d from Metadata.`Dataset` d where d.DataverseName <> \"Metadata\";","status":"fatal","timestamp":"2023-12-07T19:26:11.991Z","userAgent":"Go-http-client/1.1 (CBQ/2.0)"}

{"description":"A N1QL SELECT statement was executed","id":36867,"isAdHoc":true,"local":{"ip":"127.0.0.1","port":8095},"metrics":{"elapsedTime":309145186,"executionTime":260599632,"processedObjects":17,"resultCount":1,"resultSize":92,"warnCount":2},"name":"SELECT statement","real_userid":{"domain":"anonymous","user":"admin"},"remote":{"ip":"127.0.0.1","port":44540},"requestId":"64d208c0-e37c-42a1-aeee-d0a701f742af","statement":"with user_datasets as (select value d from Metadata.`Dataset` d where d.DataverseName <> \"Metadata\") select (select value count(*) from user_datasets d group by d.BucketName) as datasets_per_bucket, (select value count(*) from user_datasets d group by d.DataverseName) as datasets_per_dataverse, (select value count(distinct d.UUID) from Metadata.`Bucket` d where d.IsRunning) as connected_buckets;","status":"success","timestamp":"2023-12-07T19:33:28.000965Z","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:109.0) Gecko/20100101 Firefox/115.0"}

I’m curious what units the logs that do not specify a unit are supposed to be in, and whether the documentation is incorrect or if I’m just looking in the wrong location.

3

Hi, not sure I follow. Are you suggesting that “analytics” events are audited with a different format than queries? If so, do you know if the differences are documented anywhere? The page I linked in my original post was the only reference I could find that gave clear examples of what the fields should look/behave like.

4

From measuring the elapsed time on the client, you should be able to determine if 309145186 is micoseconds (309 seconds) or milliseconds (85 hours). I would venture a guess that it is micoseconds.

5

From my testing it is less than either of those, hence the ask for clarification.
Furthermore, I don’t believe I should have to guess. If the documentation tells me the only value I will get is milliseconds, that’s what I would expect (despite obvious evidence to the contrary).

6

Hello @mgillimperva
Looking at the ports, which are 8093 is for Query Service and 8095 is for Analytics Service.

The first and second requests are on port 8093 (Query Service), which are returning the unit with the time.

The 3rd request is against port 8095 (Analytics Service), which returns the time in nano-seconds, translating the time “309145186” to ~.3 seconds.

I am filing an issue for this to ensure the behavior is aligned across the services.

Thank you for bringing this up.

7

Got it, thank you for the response!
Is there somewhere I’ll be able to follow along with the status of that issue?

8

https://issues.couchbase.com/browse/MB-60090

1 Like
9

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.