Doing nothing and CPU: 8% user, 10% system

Hi,

I am wondering why ES is using 20% of my CPU, even when alone, empty and
doing nothing ?

04:05:01 PM CPU %user %nice %system %iowait %steal
%idle

04:58:01 PM all 8.34 0.00 10.23 0.00 0.00
81.43
05:00:01 PM all 8.17 0.00 10.23 0.00 0.00
81.60
05:01:01 PM all 8.45 0.00 9.80 0.00 0.00
81.75
05:02:01 PM all 8.23 0.00 9.39 0.00 0.00
82.38
05:03:01 PM all 8.80 0.00 9.09 0.00 0.00
82.11
05:04:01 PM all 8.58 0.00 9.21 0.00 0.00
82.21
05:05:01 PM all 8.30 0.00 9.88 0.00 0.00
81.82
05:06:01 PM all 8.21 0.00 9.62 0.00 0.00
82.18
05:07:01 PM all 8.16 0.00 10.01 0.00 0.00
81.82
05:08:01 PM all 8.46 0.00 9.94 0.00 0.00
81.60
05:09:01 PM all 9.68 0.00 9.80 0.00 0.00
80.53
05:10:01 PM all 8.48 0.00 10.27 0.00 0.00
81.25
05:11:01 PM all 8.43 0.00 9.88 0.00 0.00
81.69
05:12:01 PM all 8.65 0.00 10.21 0.00 0.00
81.14
05:13:01 PM all 8.44 0.00 10.65 0.00 0.00
80.91
05:14:01 PM all 8.84 0.00 10.32 0.00 0.00
80.84
05:15:01 PM all 8.46 0.00 9.10 0.00 0.00
82.44
05:16:01 PM all 7.51 0.00 7.19 0.00 0.00
85.31
05:17:01 PM all 7.62 0.00 5.97 0.00 0.00
86.40
05:18:01 PM all 6.97 0.00 7.59 0.00 0.00
85.45
05:19:01 PM all 8.32 0.00 10.86 0.00 0.00
80.82

When I do a strace -ppidof java-f, this is what I saw:

[pid 28830] <... futex resumed> ) = 0
[pid 28829] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28828] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28827] <... futex resumed> ) = 0
[pid 28830] futex(0x7f1858000bf4,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1341847402, 17956000},
ffffffff <unfinished ...>
[pid 28829] futex(0x7f18f04823c0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28828] futex(0x7f18f0570228, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28819] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28830] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28829] <... futex resumed> ) = 0
[pid 28828] <... futex resumed> ) = 0
[pid 28827] futex(0x7f186c000ab4,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1341847401, 86975000},
ffffffff <unfinished ...>
[pid 28819] futex(0x7f18f0361028, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28830] futex(0x7f18f0425e28, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28829] futex(0x7f1864002704,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1341847401, 338537606},
ffffffff <unfinished ...>
[pid 28828] futex(0x7f1860000bf4,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1341847401, 191046000},
ffffffff <unfinished ...>
[pid 28827] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28819] <... futex resumed> ) = 0
[pid 28830] <... futex resumed> ) = 0
[pid 28829] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28828] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)

...

Is it a normal behaviour ?

uname -a
Linux tpsmdt14s 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6 19:48:22 GMT 2011
x86_64 x86_64 x86_64 GNU/Linux

http://tpsmdt14s:9023/_cluster/nodes/stats
{

  • cluster_name: search-bench-different-name
  • nodes: {
    • GYRwNRHCR66FwBg7jkalow: {
      • timestamp: 1341847220159
      • name: tpsmdt14s
      • transport_address: inet[/10.26.165.17:9027]
      • hostname: tpsmdt14s
      • attributes: {
        • zone: B
          }
      • indices: {
        • store: {
          • size: 0b
          • size_in_bytes: 0
          • throttle_time: 0s
          • throttle_time_in_millis: 0
            }
        • docs: {
          • count: 0
          • deleted: 0
            }
        • indexing: {
          • index_total: 0
          • index_time: 0s
          • index_time_in_millis: 0
          • index_current: 0
          • delete_total: 0
          • delete_time: 0s
          • delete_time_in_millis: 0
          • delete_current: 0
            }
        • get: {
          • total: 0
          • time: 0s
          • time_in_millis: 0
          • exists_total: 0
          • exists_time: 0s
          • exists_time_in_millis: 0
          • missing_total: 0
          • missing_time: 0s
          • missing_time_in_millis: 0
          • current: 0
            }
        • search: {
          • query_total: 0
          • query_time: 0s
          • query_time_in_millis: 0
          • query_current: 0
          • fetch_total: 0
          • fetch_time: 0s
          • fetch_time_in_millis: 0
          • fetch_current: 0
            }
        • cache: {
          • field_evictions: 0
          • field_size: 0b
          • field_size_in_bytes: 0
          • filter_count: 0
          • filter_evictions: 0
          • filter_size: 0b
          • filter_size_in_bytes: 0
            }
        • merges: {
          • current: 0
          • current_docs: 0
          • current_size: 0b
          • current_size_in_bytes: 0
          • total: 0
          • total_time: 0s
          • total_time_in_millis: 0
          • total_docs: 0
          • total_size: 0b
          • total_size_in_bytes: 0
            }
        • refresh: {
          • total: 0
          • total_time: 0s
          • total_time_in_millis: 0
            }
        • flush: {
          • total: 0
          • total_time: 0s
          • total_time_in_millis: 0
            }
            }
            }
            }

}

$ cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 26
model name : Intel(R) Xeon(R) CPU L5520 @ 2.27GHz
stepping : 5
cpu MHz : 2266.808
cache size : 8192 KB
physical id : 0
siblings : 8
core id : 0
cpu cores : 4
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 11
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36
clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm
constant_tsc arch_perfmon pebs bts rep_good xtopology nonstop_tsc
aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm dca
sse4_1 sse4_2 popcnt lahf_lm ida dts tpr_shadow vnmi flexpriority ept vpid
bogomips : 4533.61
clflush size : 64
cache_alignment : 64
address sizes : 40 bits physical, 48 bits virtual
power management:
....
processor : 15
vendor_id : GenuineIntel
cpu family : 6
model : 26
model name : Intel(R) Xeon(R) CPU L5520 @ 2.27GHz
stepping : 5
cpu MHz : 2266.808
cache size : 8192 KB
physical id : 1
siblings : 8
core id : 3
cpu cores : 4
apicid : 23
initial apicid : 23
fpu : yes
fpu_exception : yes
cpuid level : 11
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36
clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm
constant_tsc arch_perfmon pebs bts rep_good xtopology nonstop_tsc
aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm dca
sse4_1 sse4_2 popcnt lahf_lm ida dts tpr_shadow vnmi flexpriority ept vpid
bogomips : 4532.68
clflush size : 64
cache_alignment : 64
address sizes : 40 bits physical, 48 bits virtual

$ cat /MIDDLE/smartdata/elasticsearch/conf/elasticsearch.yml

name: tpsmdt14s

The cluster name

cluster.name: search-bench-different-name

Path Settings

path:
logs: /MIDDLE/elasticsearch/logs
data: /DATAS

Force all memory to be locked, forcing the JVM to never swap

bootstrap.mlockall: false

http://www.elasticsearch.org/guide/reference/api/admin-indices-update-settings.html
index:
number_of_shards: 6
number_of_replicas: 1

http://www.elasticsearch.org/guide/reference/modules/gateway/index.html

gateway: none

http://www.elasticsearch.org/guide/reference/modules/transport.html

transport:
tcp:
port: 9027

http://www.elasticsearch.org/guide/reference/modules/http.html

http:
enabled: true
port: 9023-9023
max_content_length: 100mb

http://www.elasticsearch.org/guide/reference/modules/threadpool.html

threadpool:
index:
type: blocking
min: 100
size: 1000
wait_time: 10s

http://www.elasticsearch.org/guide/reference/modules/cluster.html

node:
zone: B
cluster.routing.allocation.awareness.attributes: zone

It was because of the leap second with the JVM

service ntpd stop
date -s "date"
service ntpd start

Now it works great.

2012/7/9 Romain filirom1@gmail.com

Hi,

I am wondering why ES is using 20% of my CPU, even when alone, empty and
doing nothing ?

04:05:01 PM CPU %user %nice %system %iowait %steal
%idle

04:58:01 PM all 8.34 0.00 10.23 0.00 0.00
81.43
05:00:01 PM all 8.17 0.00 10.23 0.00 0.00
81.60
05:01:01 PM all 8.45 0.00 9.80 0.00 0.00
81.75
05:02:01 PM all 8.23 0.00 9.39 0.00 0.00
82.38
05:03:01 PM all 8.80 0.00 9.09 0.00 0.00
82.11
05:04:01 PM all 8.58 0.00 9.21 0.00 0.00
82.21
05:05:01 PM all 8.30 0.00 9.88 0.00 0.00
81.82
05:06:01 PM all 8.21 0.00 9.62 0.00 0.00
82.18
05:07:01 PM all 8.16 0.00 10.01 0.00 0.00
81.82
05:08:01 PM all 8.46 0.00 9.94 0.00 0.00
81.60
05:09:01 PM all 9.68 0.00 9.80 0.00 0.00
80.53
05:10:01 PM all 8.48 0.00 10.27 0.00 0.00
81.25
05:11:01 PM all 8.43 0.00 9.88 0.00 0.00
81.69
05:12:01 PM all 8.65 0.00 10.21 0.00 0.00
81.14
05:13:01 PM all 8.44 0.00 10.65 0.00 0.00
80.91
05:14:01 PM all 8.84 0.00 10.32 0.00 0.00
80.84
05:15:01 PM all 8.46 0.00 9.10 0.00 0.00
82.44
05:16:01 PM all 7.51 0.00 7.19 0.00 0.00
85.31
05:17:01 PM all 7.62 0.00 5.97 0.00 0.00
86.40
05:18:01 PM all 6.97 0.00 7.59 0.00 0.00
85.45
05:19:01 PM all 8.32 0.00 10.86 0.00 0.00
80.82

When I do a strace -p pidof java -f, this is what I saw:

[pid 28830] <... futex resumed> ) = 0
[pid 28829] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28828] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28827] <... futex resumed> ) = 0
[pid 28830] futex(0x7f1858000bf4,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1341847402, 17956000},
ffffffff <unfinished ...>
[pid 28829] futex(0x7f18f04823c0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28828] futex(0x7f18f0570228, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28819] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28830] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28829] <... futex resumed> ) = 0
[pid 28828] <... futex resumed> ) = 0
[pid 28827] futex(0x7f186c000ab4,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1341847401, 86975000},
ffffffff <unfinished ...>
[pid 28819] futex(0x7f18f0361028, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28830] futex(0x7f18f0425e28, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28829] futex(0x7f1864002704,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1341847401, 338537606},
ffffffff <unfinished ...>
[pid 28828] futex(0x7f1860000bf4,
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1341847401, 191046000},
ffffffff <unfinished ...>
[pid 28827] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28819] <... futex resumed> ) = 0
[pid 28830] <... futex resumed> ) = 0
[pid 28829] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)
[pid 28828] <... futex resumed> ) = -1 ETIMEDOUT (Connection timed
out)

...

Is it a normal behaviour ?

uname -a
Linux tpsmdt14s 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6 19:48:22 GMT 2011
x86_64 x86_64 x86_64 GNU/Linux

http://tpsmdt14s:9023/_cluster/nodes/stats
{

  • cluster_name: search-bench-different-name
  • nodes: {
    • GYRwNRHCR66FwBg7jkalow: {
      • timestamp: 1341847220159
      • name: tpsmdt14s
      • transport_address: inet[/10.26.165.17:9027]
      • hostname: tpsmdt14s
      • attributes: {
        • zone: B
          }
      • indices: {
        • store: {
          • size: 0b
          • size_in_bytes: 0
          • throttle_time: 0s
          • throttle_time_in_millis: 0
            }
        • docs: {
          • count: 0
          • deleted: 0
            }
        • indexing: {
          • index_total: 0
          • index_time: 0s
          • index_time_in_millis: 0
          • index_current: 0
          • delete_total: 0
          • delete_time: 0s
          • delete_time_in_millis: 0
          • delete_current: 0
            }
        • get: {
          • total: 0
          • time: 0s
          • time_in_millis: 0
          • exists_total: 0
          • exists_time: 0s
          • exists_time_in_millis: 0
          • missing_total: 0
          • missing_time: 0s
          • missing_time_in_millis: 0
          • current: 0
            }
        • search: {
          • query_total: 0
          • query_time: 0s
          • query_time_in_millis: 0
          • query_current: 0
          • fetch_total: 0
          • fetch_time: 0s
          • fetch_time_in_millis: 0
          • fetch_current: 0
            }
        • cache: {
          • field_evictions: 0
          • field_size: 0b
          • field_size_in_bytes: 0
          • filter_count: 0
          • filter_evictions: 0
          • filter_size: 0b
          • filter_size_in_bytes: 0
            }
        • merges: {
          • current: 0
          • current_docs: 0
          • current_size: 0b
          • current_size_in_bytes: 0
          • total: 0
          • total_time: 0s
          • total_time_in_millis: 0
          • total_docs: 0
          • total_size: 0b
          • total_size_in_bytes: 0
            }
        • refresh: {
          • total: 0
          • total_time: 0s
          • total_time_in_millis: 0
            }
        • flush: {
          • total: 0
          • total_time: 0s
          • total_time_in_millis: 0
            }
            }
            }
            }

}

$ cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 26
model name : Intel(R) Xeon(R) CPU L5520 @ 2.27GHz
stepping : 5
cpu MHz : 2266.808
cache size : 8192 KB
physical id : 0
siblings : 8
core id : 0
cpu cores : 4
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 11
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat
pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm
constant_tsc arch_perfmon pebs bts rep_good xtopology nonstop_tsc
aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm dca
sse4_1 sse4_2 popcnt lahf_lm ida dts tpr_shadow vnmi flexpriority ept vpid
bogomips : 4533.61
clflush size : 64
cache_alignment : 64
address sizes : 40 bits physical, 48 bits virtual
power management:
....
processor : 15
vendor_id : GenuineIntel
cpu family : 6
model : 26
model name : Intel(R) Xeon(R) CPU L5520 @ 2.27GHz
stepping : 5
cpu MHz : 2266.808
cache size : 8192 KB
physical id : 1
siblings : 8
core id : 3
cpu cores : 4
apicid : 23
initial apicid : 23
fpu : yes
fpu_exception : yes
cpuid level : 11
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat
pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm
constant_tsc arch_perfmon pebs bts rep_good xtopology nonstop_tsc
aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm dca
sse4_1 sse4_2 popcnt lahf_lm ida dts tpr_shadow vnmi flexpriority ept vpid
bogomips : 4532.68
clflush size : 64
cache_alignment : 64
address sizes : 40 bits physical, 48 bits virtual

$ cat /MIDDLE/smartdata/elasticsearch/conf/elasticsearch.yml

name: tpsmdt14s

The cluster name

cluster.name: search-bench-different-name

Path Settings

path:
logs: /MIDDLE/elasticsearch/logs
data: /DATAS

Force all memory to be locked, forcing the JVM to never swap

bootstrap.mlockall: false

Elasticsearch Platform — Find real-time answers at scale | Elastic
index:
number_of_shards: 6
number_of_replicas: 1

Elasticsearch Platform — Find real-time answers at scale | Elastic

gateway: none

Elasticsearch Platform — Find real-time answers at scale | Elastic

transport:
tcp:
port: 9027

Elasticsearch Platform — Find real-time answers at scale | Elastic

http:
enabled: true
port: 9023-9023
max_content_length: 100mb

Elasticsearch Platform — Find real-time answers at scale | Elastic

threadpool:
index:
type: blocking
min: 100
size: 1000
wait_time: 10s

Elasticsearch Platform — Find real-time answers at scale | Elastic

node:
zone: B
cluster.routing.allocation.awareness.attributes: zone