Queries are inefficient - don't use timestamps (?)
krzysztofmaj opened this issue · 7 comments
krzysztofmaj commented
The effect (and the real problem) is that I got timeouts instead of any packets on stenoread/curl, even on simple queries like:
stenoread 'after 2017-07-31T14:05:00Z and before 2017-07-31T14:06:00Z and icmp' -n
or:
stenoread 'after 10m ago and icmp' -n
My config is:
2x Xeon E5-2660 v2
80 GB RAM
18 x 4 TB WD HDDs as JBOD for data with xfs
3 x 4 TB WD HDDs as RAID5 for indexes with xfs
Stenographer is configured to work with 18 threads - one for each disk (and not more than one thread on every physical CPU core).
1-2 Gbit/s of network traffic.
Capturing packets causes very low utilization: 4% CPU, 1% disks.
When disks are in 85% full (DiskFreePercentage=15) indexes tend to be ~4-6 TB large.
Using stenoread as from above examples causes 100% util (constant reads of 150-200 MB/s) on indexes for 15 minutes and timeouts.
Such small periods in queries (1 minute or 10 minutes) shouldn't require reading so much. Is it possible, that queries doesn't use timestamps and are trying to read whole indexes on every query?
I'm able to get results only when disks are filled in less than about 1/4. For example, if i delete all indexes and all data, I got results in seconds. Answer time increses by few seconds with every minute.
gconnell commented
Hmm, interesting.
How many index files do you have?
What SHOULD be happening is that steno should choose to read indexes only from files within the time range, due to this code: https://github.com/google/stenographer/blob/master/query/query.go#L183 (lines 183-190).
Things, then, should be pretty quick:
- read through index files, dropping those outside of time range
- read through indexes in time range, looking up seek locations for all ICMP packets
- read from packets files, at the given seek locations
krzysztofmaj commented
It's 18 (threads) folders x ~5700 files in each = ~102k files. Same amount as data files. One index file is about 70 MB.
If I calculate correctly, asking of 1 minute period means reading indexes from 3 minutes, so:
18 (threads) x 3 (minutes) * 70 MB = 3780 MB
Reading it at pace 150 MB/s should take 25 seconds. But it doesn't - it timeouts.
Adding -vvvvvvvvvvvvv to stenographer doesn't show query details in /var/log/messages.
krzysztofmaj commented
I've flushed away all data 4h ago - to be even able to make a query.
Query time constantly grows as data grows - even that I'm asking about same period. Query time for constant period should be constant - it isn't.
date; sysctl vm.drop_caches=3; time stenoread 'after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z and icmp' -n | wc -l
Tue Aug 1 12:37:48 CEST 2017
vm.drop_caches = 3
Running stenographer query 'after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z and icmp', piping to 'tcpdump -n'
reading from file /dev/stdin, link-type EN10MB (Ethernet)
58837
real 1m43.493s
user 0m0.361s
sys 0m0.161s
date; sysctl vm.drop_caches=3; time stenoread 'after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z and icmp' -n | wc -l
Tue Aug 1 13:43:46 CEST 2017
vm.drop_caches = 3
Running stenographer query 'after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z and icmp', piping to 'tcpdump -n'
reading from file /dev/stdin, link-type EN10MB (Ethernet)
58837
real 2m20.063s
user 0m0.382s
sys 0m0.190s
gconnell commented
Hmm, could you try the following:
With a bunch of files (IE: slow queries), restart stenographer adding the stenographer flag --v=10. (-vvvvv might not work, but this should).
When you run the query, you SHOULD see a bunch of lines from this log: https://github.com/google/stenographer/blob/master/query/query.go#L188
krzysztofmaj commented
After setting --v=10 there are plenty of lines like this:
Aug 3 20:02:01 nagrywajka.iadm stenographer[3915]: 2017/08/03 20:02:01 [4 5 206 254 123]
Aug 3 20:02:01 nagrywajka.iadm stenographer[3915]: 2017/08/03 20:02:01 [4 5 206 254 137]
Aug 3 20:02:01 nagrywajka.iadm stenographer[3915]: 2017/08/03 20:02:01 [4 5 208 0 249]
Aug 3 20:02:01 nagrywajka.iadm stenographer[3915]: 2017/08/03 20:02:01 [4 5 208 0 253]
Aug 3 20:02:01 nagrywajka.iadm stenographer[3915]: 2017/08/03 20:02:01 [4 5 219 30 36]
Aug 3 20:02:01 nagrywajka.iadm stenographer[3915]: 2017/08/03 20:02:01 [4 5 219 51 145]
Aug 3 20:02:01 nagrywajka.iadm stenographer[3915]: 2017/08/03 20:02:01 [4 5 225 36 141]
And there are lines like this:
Aug 3 20:02:31 nagrywajka.iadm journal: Suppressed 1270562 messages from /user.slice/user-0.slice
So I don't know, if we get all the logs from query.
After making query:
date; sysctl vm.drop_caches=3; time stenoread 'after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z and icmp' -n | wc -l
I got:
# grep -i query /var/log/messages
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX2/1501581167126981" took 180.349036ms, found 976 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX2/1501581167126981" took 180.487438ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX0/1501581044883374" took 507.626731ms, found 1146 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX0/1501581044883374" took 507.948083ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501581899110243" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501581899110243"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501581899110243" took 46.009µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX0/1501581899110243"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501581899110243" took 10.512µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501581899110243" took 87.782µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501581716026439" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501581716026439"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501581716026439" took 47.221µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501581716026439"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501581716026439" took 9.382µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501581716026439" took 99.104µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501581838096507" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501581838096507"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501581838096507" took 38.541µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX0/1501581838096507"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501581838096507" took 9.758µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501581838096507" took 82.165µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501581777059667" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501581777059667"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501581777059667" took 37.136µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX0/1501581777059667"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501581777059667" took 9.804µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501581777059667" took 87.372µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX2/1501581106113389" took 490.450904ms, found 1047 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX2/1501581106113389" took 490.576022ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX1/1501580313091513" took 862.57066ms, found 1052 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX1/1501580313091513" took 862.700358ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT1/1501580984296922" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX1/1501580984296922"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX1/1501580984296922" took 38.958µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX1/1501580984296922"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX1/1501580984296922" took 9.231µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX1/1501580984296922" took 79.162µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX1/1501580496151724" took 614.984014ms, found 1083 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX1/1501580496151724" took 615.622353ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX1/1501580740259317" took 524.314038ms, found 1085 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX1/1501580740259317" took 524.650868ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX1/1501580435122211" took 663.461661ms, found 1101 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX1/1501580435122211" took 663.589132ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX0/1501581288953769" took 646.022222ms, found 1058 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX0/1501581288953769" took 646.139612ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501582204186967" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501582204186967"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501582021123718" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501582082138086" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501582143140211" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501582143140211"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501582143140211" took 40.464µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX0/1501582143140211"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501582143140211" took 9.962µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501582143140211" took 86.532µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX2/1501580740033779" took 575.416543ms, found 1151 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX2/1501580740033779" took 575.552123ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501582021123718"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501582021123718" took 483.343µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX0/1501582021123718"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501582021123718" took 10.524µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501582021123718" took 525.534µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT0/1501581960117272" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501581960117272"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501581960117272" took 67.37µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX0/1501581960117272"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501581960117272" took 13.401µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501581960117272" took 122.982µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX0/1501582082138086"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501582082138086" took 29.426747ms, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX0/1501582082138086"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501582082138086" took 10.387µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501582082138086" took 29.475857ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX0/1501582204186967" took 44.099µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX0/1501582204186967"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX0/1501582204186967" took 17.691µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX0/1501582204186967" took 29.797115ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX2/1501580617956885" took 835.798038ms, found 1125 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX2/1501580617956885" took 835.921628ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT2/1501581411194818" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX2/1501581411194818"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT2/1501581289153595" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX2/1501581289153595"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX2/1501581289153595" took 40.349µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX2/1501581289153595"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX2/1501581289153595" took 10µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX2/1501581289153595" took 88.872µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX2/1501581411194818" took 33.564µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX2/1501581411194818"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX2/1501581411194818" took 16.655µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX2/1501581411194818" took 352.598µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT2/1501581350190997" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX2/1501581350190997"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX2/1501581350190997" took 38.205µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX2/1501581350190997"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX2/1501581350190997" took 10.689µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX2/1501581350190997" took 87.648µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX1/1501580374109371" took 729.563211ms, found 1023 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX1/1501580374109371" took 730.323841ms, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT1/1501581106386221" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX1/1501581106386221"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX1/1501581106386221" took 57.734µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX1/1501581106386221"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX1/1501581106386221" took 11.427µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX1/1501581106386221" took 102.025µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT1/1501581045349931" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX1/1501581045349931"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX1/1501581045349931" took 40.957µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX1/1501581045349931"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX1/1501581045349931" took 10.19µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX1/1501581045349931" took 124.095µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Blockfile "/tmp/stenographer027812803/PKT1/1501581167408037" looking up query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query skipping "/tmp/stenographer027812803/IDX1/1501581167408037"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "after 2017-08-01T10:00:00Z" in "/tmp/stenographer027812803/IDX1/1501581167408037" took 77.62µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 time query using "/tmp/stenographer027812803/IDX1/1501581167408037"
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "before 2017-08-01T10:01:00Z" in "/tmp/stenographer027812803/IDX1/1501581167408037" took 19.761µs, found 1 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "(after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z)" in "/tmp/stenographer027812803/IDX1/1501581167408037" took 146.522µs, found 0 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "ip proto 1" in "/tmp/stenographer027812803/IDX1/1501580618192737" took 760.385743ms, found 1092 <nil>
Aug 4 08:56:47 nagrywajka.iadm stenographer[5245]: 2017/08/04 08:56:47 Query "((after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z) and ip proto 1)" in "/tmp/stenographer027812803/IDX1/1501580618192737" took 760.53675ms, found 0 <nil>
Besides this I've set inotify to watch index directory - and there is a result from only one thread after querying:
/index/7/ ACCESS 1501662681983746
/index/7/ ACCESS 1501662620958345
/index/7/ ACCESS 1501662803995358
/index/7/ ACCESS 1501662865032778
/index/7/ ACCESS 1501662498892634
/index/7/ ACCESS 1501662437861863
/index/7/ ACCESS 1501662742994384
/index/7/ ACCESS 1501662559914299
/index/7/ ACCESS 1501662926067009
/index/7/ ACCESS 1501662987102293
/index/7/ ACCESS 1501663048102802
/index/7/ ACCESS 1501663109125677
/index/7/ ACCESS 1501662681983746
/index/7/ ACCESS 1501663231142147
/index/7/ ACCESS 1501662620958345
/index/7/ ACCESS 1501663292157904
/index/7/ ACCESS 1501663414220712
/index/7/ ACCESS 1501663170134479
/index/7/ ACCESS 1501662803995358
/index/7/ ACCESS 1501662865032778
/index/7/ ACCESS 1501663658300326
/index/7/ ACCESS 1501663353195316
/index/7/ ACCESS 1501663475257948
/index/7/ ACCESS 1501663719303896
/index/7/ ACCESS 1501663292157904
/index/7/ ACCESS 1501663780306734
/index/7/ ACCESS 1501663841324798
/index/7/ ACCESS 1501663536261392
/index/7/ ACCESS 1501663597278930
/index/7/ ACCESS 1501663902358654
/index/7/ ACCESS 1501663963390016
/index/7/ ACCESS 1501664024447707
/index/7/ ACCESS 1501663414220712
/index/7/ ACCESS 1501664085456866
/index/7/ ACCESS 1501663658300326
/index/7/ ACCESS 1501664390573640
/index/7/ ACCESS 1501664207481888
/index/7/ ACCESS 1501664512618584
/index/7/ ACCESS 1501664268523324
/index/7/ ACCESS 1501664146472479
/index/7/ ACCESS 1501664329540957
/index/7/ ACCESS 1501664451584013
/index/7/ ACCESS 1501664573626836
/index/7/ ACCESS 1501664085456866
/index/7/ ACCESS 1501663963390016
/index/7/ ACCESS 1501664695703128
/index/7/ ACCESS 1501664390573640
/index/7/ ACCESS 1501664634665873
/index/7/ ACCESS 1501664939849621
/index/7/ ACCESS 1501664878807789
/index/7/ ACCESS 1501665000893610
/index/7/ ACCESS 1501664756743945
/index/7/ ACCESS 1501664512618584
/index/7/ ACCESS 1501665061916496
/index/7/ ACCESS 1501664817794561
/index/7/ ACCESS 1501665122919214
/index/7/ ACCESS 1501664695703128
/index/7/ ACCESS 1501665244946629
/index/7/ ACCESS 1501665183924047
/index/7/ ACCESS 1501664634665873
/index/7/ ACCESS 1501665855151095
/index/7/ ACCESS 1501665916187609
/index/7/ ACCESS 1501665794114895
/index/7/ ACCESS 1501665366993052
/index/7/ ACCESS 1501665672074531
/index/7/ ACCESS 1501665305955410
/index/7/ ACCESS 1501665428019291
/index/7/ ACCESS 1501665550033713
/index/7/ ACCESS 1501665733096779
/index/7/ ACCESS 1501665611034923
/index/7/ ACCESS 1501665489023755
/index/7/ ACCESS 1501665672074531
/index/7/ ACCESS 1501665794114895
/index/7/ ACCESS 1501665855151095
/index/7/ ACCESS 1501665305955410
/index/7/ ACCESS 1501665916187609
/index/7/ ACCESS 1501665366993052
/index/7/ ACCESS 1501666038246636
/index/7/ ACCESS 1501666343337394
/index/7/ ACCESS 1501666221269979
/index/7/ ACCESS 1501666404343439
/index/7/ ACCESS 1501666465346828
/index/7/ ACCESS 1501666160263453
/index/7/ ACCESS 1501665977235631
/index/7/ ACCESS 1501666282320595
/index/7/ ACCESS 1501666526366511
/index/7/ ACCESS 1501666099257804
/index/7/ ACCESS 1501666587397133
/index/7/ ACCESS 1501666648424378
/index/7/ ACCESS 1501666343337394
/index/7/ ACCESS 1501666160263453
/index/7/ ACCESS 1501666465346828
/index/7/ ACCESS 1501666404343439
/index/7/ ACCESS 1501666221269979
/index/7/ ACCESS 1501666526366511
/index/7/ ACCESS 1501666282320595
/index/7/ ACCESS 1501666099257804
/index/7/ ACCESS 1501666038246636
/index/7/ ACCESS 1501667387099283
/index/7/ ACCESS 1501666892579652
/index/7/ ACCESS 1501667014591123
/index/7/ ACCESS 1501666831558249
/index/7/ ACCESS 1501667075645734
/index/7/ ACCESS 1501666770515426
/index/7/ ACCESS 1501667448109067
/index/7/ ACCESS 1501666709476671
/index/7/ ACCESS 1501667136703922
/index/7/ ACCESS 1501667509129338
/index/7/ ACCESS 1501666953582427
/index/7/ ACCESS 1501667197707512
/index/7/ ACCESS 1501666770515426
/index/7/ ACCESS 1501666892579652
/index/7/ ACCESS 1501667570158598
/index/7/ ACCESS 1501667014591123
/index/7/ ACCESS 1501666831558249
/index/7/ ACCESS 1501667814248154
/index/7/ ACCESS 1501667631181357
/index/7/ ACCESS 1501667692213644
/index/7/ ACCESS 1501667448109067
/index/7/ ACCESS 1501667075645734
/index/7/ ACCESS 1501667509129338
/index/7/ ACCESS 1501667387099283
/index/7/ ACCESS 1501667753235620
/index/7/ ACCESS 1501667692213644
/index/7/ ACCESS 1501667570158598
/index/7/ ACCESS 1501667631181357
So many files are accessed, >> than 3.
krzysztofmaj commented
I've changed log level to --v=2 and disabled rate limiting in journald and rsyslogd - so log now should be usefull.
Here is a query and result:
# date; sysctl vm.drop_caches=3; time stenoread 'after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z and icmp' -n | wc -l
Wed Aug 9 12:57:41 CEST 2017
vm.drop_caches = 3
Running stenographer query 'after 2017-08-01T10:00:00Z and before 2017-08-01T10:01:00Z and icmp', piping to 'tcpdump -n'
reading from file /dev/stdin, link-type EN10MB (Ethernet)
curl: (28) Operation timed out after 890001 milliseconds with 9931496 out of -1 bytes received
tcpdump: pcap_loop: truncated dump file; tried to read 94 captured bytes, only got 25
58678
real 14m50.552s
user 0m0.402s
sys 0m0.162s
gzipped log file is attached (46 MB uncompressed, almost 300k lines)
log.gz
Driste commented
Any Update? Seems like I'm running into the same issue.