Slow query logging

Support
1

Hi,

We are starting to get close to our production date (8th of January) :slight_smile: So I’m testing out the slow query logging, but I’m not getting anything in the slow_query.log file.

My settings:

# Slow Query Log
# --------------
# Logs all slow queries. A query is considered to be slow if its execution time exceeds the slow_query.time value
# defined below. 
#
# Slow log query should be enabled similar to other logs 
#
logging.slow_query.enabled = true
#
# Slow query time is specified as follows. Any query whose execution time exceed this limit will be logged in the slow
# query log. The time value should be a positive integer followed by either letter 'h' (for hours), letter 'm' (for minutes),
# letter 's' (for seconds), or letters 'ms' (for milliseconds). Examples intervals are '1h' for 1 hour, '5m' for 5 minutes,
# '90s' for 90 seconds, and '500ms' for 500 milliseconds. If no time is specified in the configuration, the default value
# of 1 minute will be used.
#
logging.slow_query.time = 500ms

The results from stardog-admin server status 

bash-4.3# stardog-admin server status
Backup Storage Directory : .backup
CPU Load                 : 0.00 %
Connection Timeout       : 1h
Export Storage Directory : .exports
Memory Direct            :  16M (Max: 1.0G)
Memory Direct Buffers    :  56K (Max: 269M)
Memory Direct Mapped     :  16M (Max: 115M)
Memory Direct Pool       :   0B (Max: 384M)
Memory Heap              : 156M (Max: 910M)
Page Cache Count         : 7
Page Cache Hit Ratio     : 94.15 %
Page Cache Memory        : 298K
Platform Arch            : amd64
Platform OS              : Linux 4.9.49-moby, Java 1.8.0_111-internal
Query All Graphs         : false
Query Timeout            : 5m
Security Disabled        : false
Slow Query Log           : true
Slow Query Threshold     : 500ms
Stardog Home             : /home/stardog/data
Stardog Version          : 5.0.5.1
Strict Parsing           : true
Uptime                   : 6 minutes 17 seconds
Databases                :
+------------+-------------+-------+---------+---------------+----------+---------+---------+---------------+----------+
|            | Connections |                Transactions                |                   Queries                    |
+------------+-------------+-------+---------+---------------+----------+---------+---------+---------------+----------+
| Name       | Open        | Open  | Total   | Avg. Time (s) | Rate/sec | Running | Total   | Avg. Time (s) | Rate/sec |
+------------+-------------+-------+---------+---------------+----------+---------+---------+---------------+----------+
| testSesame |           0 |     0 |       0 |         0.000 |    0.000 |       0 |       0 |         0.000 |    0.000 |
+------------+-------------+-------+---------+---------------+----------+---------+---------+---------------+----------+

My query (reasoning enabled). Which takes 20045 ms. Query is designed to be slow.

select (count(*) as ?count) where {

 ?a ?b ?c.
  
  optional{
  ?c ?d ?e.
    optional{
  ?e ?f ?g.
      optional {
      	?g ?h ?i.
        
      }
      }
    }
  

}

And here from the terminal

bash-4.3# stardog query -r testSesame "select (count(*) as ?count) where {
> 
>  ?a ?b ?c.
>   
>   optional{
>   ?c ?d ?e.
>     optional{
>   ?e ?f ?g.
>       optional {
>       ?g ?h ?i.
>         
>       }
>       }
>     }
>   
> 
> }"
+----------+
|  count   |
+----------+
| 52625722 |
+----------+

Query returned 1 results in 00:00:19.064
bash-4.3# cat slow_query.log 
bash-4.3#

Stardog Version: 5.0.5.1

Cheers,
Håvard

2

I'm not sure what the problem is with the logging but I wanted to mention that I wrote a trivial little plugin function for testing slow queries. It just calls sleep to make sure the query takes that much time to complete so your tests don't break when they make Stardog faster. The repo is in a bit of disarray at the moment which I hope to have cleaned up shortly. I can't quite decide how I'd like to package plugins. I'd like to allow people to only install exactly what they need but it's difficult to maintain. If anyone has any thoughts on the subject I'd love some feedback.

https://github.com/semantalytics/stardog-kibbles/tree/master/util/sleep

3

Following up on this? @stephen do you have time to test this for me?

4

Hi Håvard,

I suspect Stephen might be busy enjoying the Thanksgiving dinner today but I’ll give it a try later.

Sorry about the delay,
Pavel

5

Ahh. No worries @pavel, tell him to enjoy thanksgiving (I had forgotten it was this week). If he has time next week it would be great if he could take a look.

Håvard

6

Or if you have time that would be great too :slight_smile: Pavel.

7

Hm, I can’t reproduce the situation, I see queries with and without reasoning in the slow query log file.

Just to make sure we’re not missing anything obvious: you’re checking the slow_query.log file in $STARDOG_HOME, right? I.e. the file that the server creates on startup?

Cheers,
Pavel

8

Hi Pavel,

Good that it works for you, I guess I need to keep testing a bit here.

I am checking the slow_query.log file in $STARDOG_HOME, which gets created by stardog. The file didn’t exist until I enabled slow queries logging in the properties file.

Håvard

9

As a quick sanity check, if you reduce your slow query timeout to logging.slow_query.time=1ms can you get anything to show up in slow_query.log?

10

Hi Stephen,

Still not getting anything.

I also added logging.slow_query.type = text. This doesn’t fix it, but at least it now writes something in the log, so I know it’s not write protected.

This is what I see now:

 version: 1 timestampInMS: 1511874544911 timestampInNS: 14415968392469

Håvard

11

@stephen I think i have a lead.

When I create a new DB from the web gui, slow query logging works fine for that database.

However, the database that I’ve created from the terminal doesn’t log anything. Here is how i created the database.

stardog-admin db create -n testSesame \
    -o security.named.graphs=true  \
    icv.enabled=true \
    icv.reasoning.enabled=true \
    icv.active.graphs=http://data.einnsyn.no/osloKommuneVirksomheterGraph,http://data.einnsyn.no/virksomheterGraph,http://data.einnsyn.no/brukereGraph,http://data.einnsyn.no/innsynskravGraph,http://www.arkivverket.no/standarder/noark5/arkivstruktur/ontologyGraph   \
    preserve.bnode.ids=true \
    query.pp.contexts=true \
    query.all.graphs=true \
    reasoning.type=SL \
    reasoning.schema.graphs=http://www.arkivverket.no/standarder/noark5/arkivstruktur/ontologyGraph \
    --
12

What if anything is in your stardog.properties file?

13

Makes no difference if I have my stardog.properties file set up correctly before I create the database, or if I set it up after.

14

@stephen did you manage to reproduce it with the command for creating a database that I posted? I wonder if this is related to query timeout not seeming to work for us and no queries showing up in the running queries page in the web gui?

15

@hmottestad I am absolutely able to reproduce your issue with that command. I will continue looking into this and report back here.

1 Like
16

Update: We have determined the cause of this problem and opened issue #4513 to address it in an upcoming release

17

Thanks Stephen.

Håvard

18

I realize I didn’t actually explain the problem… Something with named graph security is causing the slow query log not to work correctly. So if you’re testing or otherwise in a position where you don’t need named graph security enabled, you can verify that it does in fact work.

19

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