stats REST API call under-counts 'get's (queries by ID)

[buildlackey]

Elasticsearch version (bin/elasticsearch --version):

"version" : {
"number" : "5.4.1",
"build_hash" : "2cfe0df",
"build_date" : "2017-05-29T16:05:51.443Z",
"build_snapshot" : false,
"lucene_version" : "6.5.1"
},

Plugins installed: []

$ ls /apps/elasticsearch/plugins/
analysis-icu analysis-kuromoji mapper-murmur3 raigad-discovery repository-s3

JVM version (java -version):

java version "1.8.0_131"

OS version (uname -a if on a Unix-like system):
4.4.0-81-generic #104-Ubuntu SMP Wed Jun 14 08:17:06 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:

My assumption in reporting this issue is that the _stats API call will return
a JSON attribute that corresponds to the number of times a particular index was
queried directly by object ID, and that this attribute has the following coordinates
(in the returned JSON):

    <root>
        <indices>
            <index-name>
                <primaries>
                    <get>   
                        <total>

If that assumption is correct, then it is easy to reproduce a failure where
the number of 'gets' reported by _stats does not match the number of requests issued,
even after a number of minutes pass to let the metrics be published to the latest values.

Steps to reproduce:

(These steps assume you have the tool 'jq' installed to parse JSON responses.)

The script below queries an index 10 times directly by id (with a sleep just in case
the count is thrown off by requests arriving too closely spaced between each other).

Then it sleeps another minute to let metrics be published, then it issues a _stats
call to get the number of 'gets' in the index 'pest'.

The result I get is 3, even though I issue 10 gets. Even after 5 minutes elapses
when I check again the result is still 3.

cluster=http://localhost:9200
curl -X PUT $cluster/pest/mouse/1 -d '{ "sound": "squeak" }'

curl $cluster/pest/mouse/1 # get 10 times
sleep 1
curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/1

sleep 60 # sleep to give time for metrics to be published

curl -X GET $cluster/_all/_stats?pretty | jq ".indices.pest.primaries.get.total"

[colings86]

@buildlackey is this a single node cluster? I notice in your reproduction step you look at .indices.pest.primaries.get.total which will only give you the number of requests to a primary shard and will not count requests to replicas. If you have multiple nodes in your cluster then witht he default settings you will have 1 primary and 1 replica for each shard of the pest index so it could well be that we hit the primary only 3 times because the request was sent to the replica the other 7 times. Could you see what the value of .indices.pest.total.get.total is?

[buildlackey]

What you said makes a lot of sense. I combined your suggestion with an observation from my colleague @gndcshv where he pointed out that since i was asking for the same ID there might be some caching before the request hit elastic search. better to use different ID's. So, I combined those 2 suggestions and now i get expected behavior.. So.. Not a bug ! thnx !

The new verification script is:

cluster=http://localhost:9200
curl -X PUT $cluster/pest/mouse/1 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/2 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/3 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/4 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/5 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/6 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/7 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/8 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/9 -d '{ "sound": "squeak" }'
curl -X PUT $cluster/pest/mouse/0 -d '{ "sound": "squeak" }'

curl $cluster/pest/mouse/1
sleep 1
curl $cluster/pest/mouse/2
sleep 1
curl $cluster/pest/mouse/3
sleep 1
curl $cluster/pest/mouse/4
sleep 1
curl $cluster/pest/mouse/5
sleep 1
curl $cluster/pest/mouse/6
sleep 1
curl $cluster/pest/mouse/7
sleep 1
curl $cluster/pest/mouse/8
sleep 1
curl $cluster/pest/mouse/9
sleep 1
curl $cluster/pest/mouse/0

sleep 60

curl -X GET $cluster/_all/_stats?pretty | jq ".indices.pest.primaries.get.total" # this returns only 2
curl -X GET $cluster/_all/_stats?pretty | jq ".indices.pest.total.get.total" # this returns 10, which is correct !