# Java sleep (Redundancy in logging “Flushing buffer at interval”)

**URL:** https://discuss.elastic.co/t/java-sleep-redundancy-in-logging-flushing-buffer-at-interval/68527
**Category:** Logstash
**Created:** [December 9, 2016, 8:19am UTC](https://discuss.elastic.co/t/java-sleep-redundancy-in-logging-flushing-buffer-at-interval/68527 "2016-12-09T08:19:03Z")
**Posts on this page:** 6
**Page:** 1

<div class="post-metadata">

### Author: ![extremeblue](https://avatars.discourse-cdn.com/v4/letter/e/c4cdca/32.png) [@extremeblue](https://discuss.elastic.co/u/extremeblue)
#### Post date: [December 9, 2016, 8:19am UTC](https://discuss.elastic.co/t/java-sleep-redundancy-in-logging-flushing-buffer-at-interval/68527/1 "2016-12-09T08:19:03Z")

</div>

I'm using logstash 2.3.2(jdbc input/elasticsearch output) and elasticsearch 2.3.3 from CentOS7.

process status:

> Name: java  
> State: S (sleeping)  
> Tgid: 4486  
> Ngid: 0  
> Pid: 4486  
> PPid: 4485  
> TracerPid: 0  
> Uid: 1000 1000 1000 1000  
> Gid: 1000 1000 1000 1000  
> FDSize: 256  
> Groups: 10 1000  
> VmPeak: 7406444 kB  
> VmSize: 7305992 kB  
> VmLck: 0 kB  
> VmPin: 0 kB  
> VmHWM: 697632 kB  
> VmRSS: 697632 kB  
> VmData: 7094780 kB  
> VmStk: 136 kB  
> VmExe: 4 kB  
> VmLib: 22752 kB  
> VmPTE: 2032 kB  
> VmSwap: 0 kB  
> Threads: 35  
> SigQ: 1/256556  
> SigPnd: 0000000000000000  
> ShdPnd: 0000000000000000  
> SigBlk: 0000000000000000  
> SigIgn: 0000000000001000  
> SigCgt: 2000000181004ccf  
> CapInh: 0000000000000000  
> CapPrm: 0000000000000000  
> CapEff: 0000000000000000  
> CapBnd: 0000001fffffffff  
> Seccomp: 0  
> Cpus\_allowed: fff  
> Cpus\_allowed\_list: 0-11  
> Mems\_allowed: 00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001  
> Mems\_allowed\_list: 0  
> voluntary\_ctxt\_switches: 26  
> nonvoluntary\_ctxt\_switches: 5

my logstash log:

> {:timestamp=\>"2016-12-05T13:34:36.911000+0900", :message=\>"closing output delegator", :klass=\>LogStash::Outputs::Elasticsearch, :level=\>:debug, :file=\>"logstash/output\_delegator.rb", :line=\>"137", :method=\>"do\_close"}  
> {:timestamp=\>"2016-12-05T13:34:36.911000+0900", :message=\>"closing", :plugin=\>\<LogStash::Outputs::Elasticsearch hosts=\>["localhost:29200"], index=\>"sz\_20161205133401", document\_type=\>"%{type}", document\_id=\>"%{cs\_sn}", routing=\>"%{hb\_sn}", parent=\>"%{cs\_sn}", codec=\>\<LogStash::Codecs::Plain charset=\>"UTF-8"\>, workers=\>1, manage\_template=\>true, template\_name=\>"logstash", template\_overwrite=\>false, flush\_size=\>500, idle\_flush\_time=\>1, doc\_as\_upsert=\>false, max\_retries=\>3, script\_type=\>"inline", script\_var\_name=\>"event", scripted\_upsert=\>false, retry\_max\_interval=\>2, retry\_max\_items=\>500, retry\_on\_conflict=\>1, action=\>"index", path=\>"/", ssl\_certificate\_verification=\>true, sniffing=\>false, sniffing\_delay=\>5\>, :level=\>:debug, :file=\>"logstash/plugin.rb", :line=\>"35", :method=\>"do\_close"}  
> {:timestamp=\>"2016-12-05T13:34:37.512000+0900", :message=\>"Flushing buffer at interval", :instance=\>"#\<LogStash::Outputs::Elasticsearch::Buffer:0x22da17b4 @stopping=#Concurrent::AtomicBoolean:0x1c4a3c4c, @last\_flush=2016-12-05 13:34:36 +0900, @flush\_thread=#\<Thread:0x1ecc9c39 run\>, @max\_size=500, @operations\_lock=#Java::JavaUtilConcurrentLocks::ReentrantLock:0x5b71b74, @submit\_proc=#Proc:0x11519466@/home/admin/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.6.2-java/lib/logstash/outputs/elasticsearch/common.rb:57, @flush\_interval=1, @logger=#\<Cabin::Channel:0xeb56a28 @subscriber\_lock=#Mutex:0x284c6fa3, @data={}, @metrics=#\<Cabin::Metrics:0x32354b00 @channel=#\<Cabin::Channel:0xeb56a28 ...\>, @metrics={}, @metrics\_lock=#Mutex:0xfc44c98\>, @subscribers={12378=\>#\<Cabin::Subscriber:0x5a49781d @options={}, @output=#\<Cabin::Outputs::IO:0x65edf5a0 @lock=#Mutex:0x69990fa7, @io=#\<File:logstash\_sz\_start.out\>\>\>}, @level=:debug\>, @buffer=, @operations\_mutex=#Mutex:0x3a6696fb\>", :interval=\>1, :level=\>:debug, :file=\>"logstash/outputs/elasticsearch/buffer.rb", :line=\>"90", :method=\>"interval\_flush"}  
> {:timestamp=\>"2016-12-05T13:34:37.512000+0900", :message=\>"Flushing buffer at interval", :instance=\>"#\<LogStash::Outputs::Elasticsearch::Buffer:0x22da17b4 @stopping=#Concurrent::AtomicBoolean:0x1c4a3c4c, @last\_flush=2016-12-05 13:34:36 +0900, @flush\_thread=#\<Thread:0x1ecc9c39 run\>, @max\_size=500, @operations\_lock=#Java::JavaUtilConcurrentLocks::ReentrantLock:0x5b71b74, @submit\_proc=#Proc:0x11519466@/home/admin/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.6.2-java/lib/logstash/outputs/elasticsearch/common.rb:57, @flush\_interval=1, @logger=#\<Cabin::Channel:0xeb56a28 @subscriber\_lock=#Mutex:0x284c6fa3, @data={}, @metrics=#\<Cabin::Metrics:0x32354b00 @channel=#\<Cabin::Channel:0xeb56a28 ...\>, @metrics={}, @metrics\_lock=#Mutex:0xfc44c98\>, @subscribers={12378=\>#\<Cabin::Subscriber:0x5a49781d @options={}, @output=#\<Cabin::Outputs::IO:0x65edf5a0 @lock=#Mutex:0x69990fa7, @io=#\<File:logstash\_sz\_start.out\>\>\>}, @level=:debug\>, @buffer=, @operations\_mutex=#Mutex:0x3a6696fb\>", :interval=\>1, :level=\>:debug, :file=\>"logstash/outputs/elasticsearch/buffer.rb", :line=\>"90", :method=\>"interval\_flush"}  
> ...

I wanna know why logstash is sleeping.

---

<div class="post-metadata">

### Author: ![jordansissel](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/jordansissel/32/44957_2.png) [@jordansissel](https://discuss.elastic.co/u/jordansissel)
#### Post date: [December 11, 2016, 4:25am UTC](https://discuss.elastic.co/t/java-sleep-redundancy-in-logging-flushing-buffer-at-interval/68527/2 "2016-12-11T04:25:24Z")

</div>

> [@extremeblue](#):
>
> Name: javaState: S (sleeping)Tgid: 4486Ngid: 0Pid: 4486PPid: 4485

Logstash runs with many many threads. Based on your output (quoted above) this is only showing a single thread and that thread, when you observe it, is sleeping (waiting on some external condition, perhaps, I dont' know). This doesn't show you what the whole process (many threads) is doing at the time of your observation.

Based on what I see here, something has told Logstash to terminate (indicated bythe `closing output delegator` text; outputs only close when Logstash is shutting down or the pipeline is reloaded, I think?).

Anyway, your question about "Flushing buffer at interval" -- this is a normal message from Logstash.

What behavior is causing you to investigate these things? This is OK to investigate, but I wonder what problem you are having - with more information we may be able to help better.

---

<div class="post-metadata">

### Author: ![extremeblue](https://avatars.discourse-cdn.com/v4/letter/e/c4cdca/32.png) [@extremeblue](https://discuss.elastic.co/u/extremeblue)
#### Post date: [December 12, 2016, 4:28am UTC](https://discuss.elastic.co/t/java-sleep-redundancy-in-logging-flushing-buffer-at-interval/68527/3 "2016-12-12T04:28:51Z")

</div>

Dear jordansissel,

Thanks for your reply.

I've batching small documents(about 60,000 docs, 60Mi size) with a crontab(replacing index alias) by one minute unit.  
Sometimes, the same phenomenon occurred.  
Here is a part of the elasticsearch debug level log:

> [2016-12-12 09:13:20,009][DEBUG][indices.memory] [N4] recalculating shard indexing buffer, total is [810.8mb] with [3] active shards, each shard set to indexing=[270.2mb], translog=[64kb]  
> [2016-12-12 09:13:44,012][DEBUG][cluster.service] [N4] processing [index-aliases]: execute  
> [2016-12-12 09:13:44,013][DEBUG][cluster.service] [N4] cluster state updated, version [304], source [index-aliases]  
> [2016-12-12 09:13:44,013][DEBUG][cluster.service] [N4] publishing cluster state version [304]  
> [2016-12-12 09:13:44,014][DEBUG][cluster.service] [N4] set local cluster state to version 304  
> [2016-12-12 09:13:44,029][DEBUG][cluster.service] [N4] processing [index-aliases]: took 16ms done applying updated cluster\_state (version: 304, uuid: 0qKe9b4oRKiY0HyDTNgyVg)  
> [2016-12-12 09:13:44,038][DEBUG][cluster.service] [N4] processing [delete-index [sz\_20161212091101]]: execute  
> [2016-12-12 09:13:44,038][DEBUG][cluster.metadata] [N4] [sz\_20161212091101] deleting index  
> [2016-12-12 09:13:44,039][DEBUG][cluster.service] [N4] cluster state updated, version [305], source [delete-index [sz\_20161212091101]]  
> [2016-12-12 09:13:44,039][DEBUG][cluster.service] [N4] publishing cluster state version [305]  
> [2016-12-12 09:13:44,039][DEBUG][cluster.service] [N4] set local cluster state to version 305  
> [2016-12-12 09:13:44,040][DEBUG][indices.cluster] [N4] [sz\_20161212091101] cleaning index, no longer part of the metadata  
> [2016-12-12 09:13:44,040][DEBUG][indices] [N4] [sz\_20161212091101] closing ... (reason [index no longer part of the metadata])  
> [2016-12-12 09:13:44,040][DEBUG][indices] [N4] [sz\_20161212091101] closing index service (reason [index no longer part of the metadata])  
> [2016-12-12 09:13:44,040][DEBUG][index] [N4] [sz\_20161212091101] [0] closing... (reason: [index no longer part of the metadata])  
> [2016-12-12 09:13:44,040][DEBUG][index.shard] [N4] [sz\_20161212091101][0] state: [STARTED]-\>[CLOSED], reason [index no longer part of the metadata]  
> [2016-12-12 09:13:44,040][DEBUG][index.shard] [N4] [sz\_20161212091101][0] operations counter reached 0, will not accept any further writes  
> [2016-12-12 09:13:44,040][DEBUG][index.engine] [N4] \> [sz\_20161212091101][0] close now acquiring writeLock  
> [2016-12-12 09:35:20,164][DEBUG][indices.memory] [N4] recalculating shard indexing buffer, total is [810.8mb] with [1] active shards, each shard set to indexing=[512mb], translog=[64kb]  
> [2016-12-12 09:35:50,164][DEBUG][index.shard] [N4] [sz\_20161212093001][0] updating index\_buffer\_size from [512mb] to [500kb]; IndexWriter now using [0] bytes  
> [2016-12-12 09:35:50,165][DEBUG][index.shard] [N4] [sz\_20161212093001][0] marking shard as inactive (inactive\_time=[300000000000]) indexing wise  
> [2016-12-12 09:35:50,231][DEBUG][index.engine] [N4] [sz\_20161212093001][0] successfully sync committed. sync id [AVjwdQNKeDHUNSVSe1SS].  
> [2016-12-12 09:36:05,950][DEBUG][index.fielddata.plain] [N4] [sz\_20161212092901] Global-ordinals[fe\_ext][8] took 0 ms

Regards jordansissel

---

<div class="post-metadata">

### Author: ![jordansissel](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/jordansissel/32/44957_2.png) [@jordansissel](https://discuss.elastic.co/u/jordansissel)
#### Post date: [December 12, 2016, 6:04am UTC](https://discuss.elastic.co/t/java-sleep-redundancy-in-logging-flushing-buffer-at-interval/68527/4 "2016-12-12T06:04:48Z")

</div>

When I read your Elasticsearch log, i don't see anything problematic :\

---

<div class="post-metadata">

### Author: ![extremeblue](https://avatars.discourse-cdn.com/v4/letter/e/c4cdca/32.png) [@extremeblue](https://discuss.elastic.co/u/extremeblue)
#### Post date: [December 12, 2016, 6:29am UTC](https://discuss.elastic.co/t/java-sleep-redundancy-in-logging-flushing-buffer-at-interval/68527/5 "2016-12-12T06:29:24Z")

</div>

Sorry, I feel the same way :`(

---

<div class="post-metadata">

### Author: ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)
#### Post date: [January 9, 2017, 6:30am UTC](https://discuss.elastic.co/t/java-sleep-redundancy-in-logging-flushing-buffer-at-interval/68527/6 "2017-01-09T06:30:20Z")

</div>

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