Java Client write timeout exception


#1

for com.aerospike.client.AerospikeException$Timeout: Client timeout: timeout=0 iterations=3 failedNodes=0 failedConns=0,

  • it means it has retried for 3 times already, right?
  • My code leave maxRetries(3), sleepBetweenRetries(500ms) and timeout(0) in WritePolicy by default. So the above error means, request #1 -> (socket fail to connect?) -> sleep 500ms #1 -> request #2 (socket fail to connect?) -> sleep 500ms #2 -> request #3 -> (socket fail to connect?) -> Timeout Exception
  • So a timeout 0 in WritePolicy means zero tolerant, immediately consider as failed, instead of wait infinitely. I tried to set the timeout to 100 (suppose to be in milliseconds), and then the exception throw in iterations=1 without any retry any more. Is it an expected behavior? i suppose timeout=100 should still following the maxRetries policy.

#2

Hi

Timeout of zero means that there is no timeout. In you example, you will try the operation 3 times, with a 500ms wait between each try. If you have not been successful after 1.5 seconds you will get an exception.

Timeout trumps retries. If you set a time out of 50ms (rather than zero) and the operation has not completed in that time, you will get an exception regardless of the number of retries.

Does this help?


#3

I connected the server (CE 3.5.3) runing on my pc and encountered the same problem.


#4

Hi youn_bie

Can you elaborate on your problem so I can help?

Peter


#5

Hi helipilot50 :

I installed the CE 3.5.3 on my PC, then run the java client example throws exception described as bellow.

/run_examples -h localhost -p 3000 -n test -s demoset PutGet 2015-03-11 20:43:21 CST INFO Add node BB9449B93D9BED4 127.0.0.1:3000 2015-03-11 20:43:21 CST INFO PutGet Begin 2015-03-11 20:43:21 CST INFO Put: namespace=test set=demoset key=putgetkey bin1=bin1 value1=value1 bin2=bin2 value2=value2

Client timeout: timeout=0 iterations=2 failedNodes=0 failedConns=0 com.aerospike.client.AerospikeException$Timeout: Client timeout: timeout=0 iterations=2 failedNodes=0 failedConns=0 at com.aerospike.client.command.SyncCommand.execute(SyncCommand.java:131) at com.aerospike.client.AerospikeClient.put(AerospikeClient.java:299) at com.aerospike.examples.PutGet.runMultiBinTest(PutGet.java:55) at com.aerospike.examples.PutGet.runExample(PutGet.java:39) at com.aerospike.examples.Example.run(Example.java:80) at com.aerospike.examples.Example.runExample(Example.java:65) at com.aerospike.examples.Example.runExamples(Example.java:47) at com.aerospike.examples.Main.runExamples(Main.java:198) at com.aerospike.examples.Main.main(Main.java:122)


#6

Try aql, also found error like this :

aql> insert into test.demo(PK, bin) values (‘key’ , ‘Bin Value’) Error: (9) Client timeout: timeout=1000 iterations=1 failedNodes=0 failedConns=0


#7

The aerospike server in running on my pC (Ubuntu 12.04) with the default aerospike,conf.


#8

Can you provide the output of your ifconfig?

sudo ifconfig

and ensure that server started

sudo service aerospike status 

and provide last 100 lines of your server logs:

sudo tail -n 100 /var/log/aerospike/aerospike.log

#9

hi, lucien :

sudo ifconfig
output :  
inet address :10.236.121.46

sudo service aerospike status
output :  * asd is running

sudo tail -n 100 /var/log/aerospike/aerospike.log
output:

Mar 16 2015 06:31:43 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
Mar 16 2015 06:31:43 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4580)  system memory: free 5142968kb ( 63 percent free ) 
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4588)  migrates in progress ( 0 , 0 ) ::: ClusterSize 1 ::: objects 1 ::: sub_objects 0
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4596)  rec refs 1 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 0
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4602)  replica errs :: null 0 non-null 0 ::: sync copy errs :: node 0 :: master 0 
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4612)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: bq 0 ::: iq 0 ::: dq 0 : fds - proto (0, 13, 13) : hb (0, 0, 0) : fab (21, 212, 191)
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4614)    heartbeat_received: self 1647296 : foreign 1718428
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4615)    heartbeat_stats: bt 0 bf 0 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 0 mrf 0 eh 3 efd 3 efa 0 um 0 mcf 0 rc 0 
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4628)    tree_counts: nsup 0 scan 0 batch 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 0
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4644) namespace test: disk inuse: 0 memory inuse: 98 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4644) namespace bar: disk inuse: 0 memory inuse: 0 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4689)    partitions: actual 8192 sync 0 desync 0 zombie 0 wait 0 absent 0
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (1 total) msec
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: writes_reply (1 total) msec
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
Mar 16 2015 06:31:48 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
Mar 16 2015 06:31:48 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
Mar 16 2015 06:31:53 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
Mar 16 2015 06:31:53 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4580)  system memory: free 5140772kb ( 63 percent free ) 
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4588)  migrates in progress ( 0 , 0 ) ::: ClusterSize 1 ::: objects 1 ::: sub_objects 0
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4596)  rec refs 1 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 0
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4602)  replica errs :: null 0 non-null 0 ::: sync copy errs :: node 0 :: master 0 
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4612)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: bq 0 ::: iq 0 ::: dq 0 : fds - proto (0, 13, 13) : hb (0, 0, 0) : fab (21, 212, 191)
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4614)    heartbeat_received: self 1647362 : foreign 1718561
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4615)    heartbeat_stats: bt 0 bf 0 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 0 mrf 0 eh 3 efd 3 efa 0 um 0 mcf 0 rc 0 
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4628)    tree_counts: nsup 0 scan 0 batch 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 0
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4644) namespace test: disk inuse: 0 memory inuse: 98 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4644) namespace bar: disk inuse: 0 memory inuse: 0 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4689)    partitions: actual 8192 sync 0 desync 0 zombie 0 wait 0 absent 0
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (1 total) msec
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: writes_reply (1 total) msec
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
Mar 16 2015 06:31:57 GMT: INFO (nsup): (thr_nsup.c::1226) {test} nsup start
Mar 16 2015 06:31:57 GMT: INFO (nsup): (thr_nsup.c::1144) {test} Records: 1, 0 0-vt, 0(0) expired, 0(0) evicted, 0(0) set deletes, 0(0) set evicted. Evict ttls: 0,0,0.000. Waits: 0,0,0. Total time: 3 ms
Mar 16 2015 06:31:57 GMT: INFO (nsup): (thr_nsup.c::1226) {bar} nsup start
Mar 16 2015 06:31:57 GMT: INFO (nsup): (thr_nsup.c::1144) {bar} Records: 0, 0 0-vt, 0(0) expired, 0(0) evicted, 0(0) set deletes, 0(0) set evicted. Evict ttls: 0,0,0.000. Waits: 0,0,0. Total time: 4 ms
Mar 16 2015 06:31:58 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
Mar 16 2015 06:31:58 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
Mar 16 2015 06:32:03 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
Mar 16 2015 06:32:03 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4580)  system memory: free 5135964kb ( 63 percent free ) 
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4588)  migrates in progress ( 0 , 0 ) ::: ClusterSize 1 ::: objects 1 ::: sub_objects 0
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4596)  rec refs 1 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 0
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4602)  replica errs :: null 0 non-null 0 ::: sync copy errs :: node 0 :: master 0 
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4612)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: bq 0 ::: iq 0 ::: dq 0 : fds - proto (0, 13, 13) : hb (0, 0, 0) : fab (21, 212, 191)
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4614)    heartbeat_received: self 1647429 : foreign 1718693
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4615)    heartbeat_stats: bt 0 bf 0 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 0 mrf 0 eh 3 efd 3 efa 0 um 0 mcf 0 rc 0 
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4628)    tree_counts: nsup 0 scan 0 batch 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 0
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4644) namespace test: disk inuse: 0 memory inuse: 98 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4644) namespace bar: disk inuse: 0 memory inuse: 0 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4689)    partitions: actual 8192 sync 0 desync 0 zombie 0 wait 0 absent 0
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (1 total) msec
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: writes_reply (1 total) msec
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
Mar 16 2015 06:32:08 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
Mar 16 2015 06:32:08 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
Mar 16 2015 06:32:13 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
Mar 16 2015 06:32:13 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4580)  system memory: free 5138880kb ( 63 percent free ) 
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4588)  migrates in progress ( 0 , 0 ) ::: ClusterSize 1 ::: objects 1 ::: sub_objects 0
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4596)  rec refs 1 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 0
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4602)  replica errs :: null 0 non-null 0 ::: sync copy errs :: node 0 :: master 0 
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4612)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: bq 0 ::: iq 0 ::: dq 0 : fds - proto (0, 13, 13) : hb (0, 0, 0) : fab (21, 212, 191)
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4614)    heartbeat_received: self 1647495 : foreign 1718826
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4615)    heartbeat_stats: bt 0 bf 0 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 0 mrf 0 eh 3 efd 3 efa 0 um 0 mcf 0 rc 0 
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4628)    tree_counts: nsup 0 scan 0 batch 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 0
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4644) namespace test: disk inuse: 0 memory inuse: 98 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4644) namespace bar: disk inuse: 0 memory inuse: 0 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4689)    partitions: actual 8192 sync 0 desync 0 zombie 0 wait 0 absent 0
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (1 total) msec
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: writes_reply (1 total) msec
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
Mar 16 2015 06:32:18 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
Mar 16 2015 06:32:18 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8

#10

sudo tail -n 100 /var/log/aerospike/aerospike.log

output:

Mar 16 2015 06:31:43 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
    Mar 16 2015 06:31:43 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4580)  system memory: free 5142968kb ( 63 percent free ) 
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4588)  migrates in progress ( 0 , 0 ) ::: ClusterSize 1 ::: objects 1 ::: sub_objects 0
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4596)  rec refs 1 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 0
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4602)  replica errs :: null 0 non-null 0 ::: sync copy errs :: node 0 :: master 0 
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4612)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: bq 0 ::: iq 0 ::: dq 0 : fds - proto (0, 13, 13) : hb (0, 0, 0) : fab (21, 212, 191)
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4614)    heartbeat_received: self 1647296 : foreign 1718428
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4615)    heartbeat_stats: bt 0 bf 0 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 0 mrf 0 eh 3 efd 3 efa 0 um 0 mcf 0 rc 0 
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4628)    tree_counts: nsup 0 scan 0 batch 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 0
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4644) namespace test: disk inuse: 0 memory inuse: 98 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4644) namespace bar: disk inuse: 0 memory inuse: 0 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
    Mar 16 2015 06:31:45 GMT: INFO (info): (thr_info.c::4689)    partitions: actual 8192 sync 0 desync 0 zombie 0 wait 0 absent 0
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (1 total) msec
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: writes_reply (1 total) msec
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
    Mar 16 2015 06:31:45 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
    Mar 16 2015 06:31:48 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
    Mar 16 2015 06:31:48 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
    Mar 16 2015 06:31:53 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
    Mar 16 2015 06:31:53 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4580)  system memory: free 5140772kb ( 63 percent free ) 
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4588)  migrates in progress ( 0 , 0 ) ::: ClusterSize 1 ::: objects 1 ::: sub_objects 0
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4596)  rec refs 1 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 0
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4602)  replica errs :: null 0 non-null 0 ::: sync copy errs :: node 0 :: master 0 
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4612)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: bq 0 ::: iq 0 ::: dq 0 : fds - proto (0, 13, 13) : hb (0, 0, 0) : fab (21, 212, 191)
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4614)    heartbeat_received: self 1647362 : foreign 1718561
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4615)    heartbeat_stats: bt 0 bf 0 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 0 mrf 0 eh 3 efd 3 efa 0 um 0 mcf 0 rc 0 
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4628)    tree_counts: nsup 0 scan 0 batch 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 0
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4644) namespace test: disk inuse: 0 memory inuse: 98 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4644) namespace bar: disk inuse: 0 memory inuse: 0 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
    Mar 16 2015 06:31:55 GMT: INFO (info): (thr_info.c::4689)    partitions: actual 8192 sync 0 desync 0 zombie 0 wait 0 absent 0
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (1 total) msec
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: writes_reply (1 total) msec
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
    Mar 16 2015 06:31:55 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
    Mar 16 2015 06:31:57 GMT: INFO (nsup): (thr_nsup.c::1226) {test} nsup start
    Mar 16 2015 06:31:57 GMT: INFO (nsup): (thr_nsup.c::1144) {test} Records: 1, 0 0-vt, 0(0) expired, 0(0) evicted, 0(0) set deletes, 0(0) set evicted. Evict ttls: 0,0,0.000. Waits: 0,0,0. Total time: 3 ms
    Mar 16 2015 06:31:57 GMT: INFO (nsup): (thr_nsup.c::1226) {bar} nsup start
    Mar 16 2015 06:31:57 GMT: INFO (nsup): (thr_nsup.c::1144) {bar} Records: 0, 0 0-vt, 0(0) expired, 0(0) evicted, 0(0) set deletes, 0(0) set evicted. Evict ttls: 0,0,0.000. Waits: 0,0,0. Total time: 4 ms
    Mar 16 2015 06:31:58 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
    Mar 16 2015 06:31:58 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
    Mar 16 2015 06:32:03 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
    Mar 16 2015 06:32:03 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4580)  system memory: free 5135964kb ( 63 percent free ) 
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4588)  migrates in progress ( 0 , 0 ) ::: ClusterSize 1 ::: objects 1 ::: sub_objects 0
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4596)  rec refs 1 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 0
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4602)  replica errs :: null 0 non-null 0 ::: sync copy errs :: node 0 :: master 0 
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4612)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: bq 0 ::: iq 0 ::: dq 0 : fds - proto (0, 13, 13) : hb (0, 0, 0) : fab (21, 212, 191)
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4614)    heartbeat_received: self 1647429 : foreign 1718693
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4615)    heartbeat_stats: bt 0 bf 0 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 0 mrf 0 eh 3 efd 3 efa 0 um 0 mcf 0 rc 0 
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4628)    tree_counts: nsup 0 scan 0 batch 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 0
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4644) namespace test: disk inuse: 0 memory inuse: 98 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4644) namespace bar: disk inuse: 0 memory inuse: 0 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
    Mar 16 2015 06:32:05 GMT: INFO (info): (thr_info.c::4689)    partitions: actual 8192 sync 0 desync 0 zombie 0 wait 0 absent 0
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (1 total) msec
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: writes_reply (1 total) msec
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
    Mar 16 2015 06:32:05 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
    Mar 16 2015 06:32:08 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
    Mar 16 2015 06:32:08 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
    Mar 16 2015 06:32:13 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
    Mar 16 2015 06:32:13 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4580)  system memory: free 5138880kb ( 63 percent free ) 
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4588)  migrates in progress ( 0 , 0 ) ::: ClusterSize 1 ::: objects 1 ::: sub_objects 0
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4596)  rec refs 1 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 0
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4602)  replica errs :: null 0 non-null 0 ::: sync copy errs :: node 0 :: master 0 
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4612)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: bq 0 ::: iq 0 ::: dq 0 : fds - proto (0, 13, 13) : hb (0, 0, 0) : fab (21, 212, 191)
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4614)    heartbeat_received: self 1647495 : foreign 1718826
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4615)    heartbeat_stats: bt 0 bf 0 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 0 mrf 0 eh 3 efd 3 efa 0 um 0 mcf 0 rc 0 
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4628)    tree_counts: nsup 0 scan 0 batch 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 0
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4644) namespace test: disk inuse: 0 memory inuse: 98 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4644) namespace bar: disk inuse: 0 memory inuse: 0 (bytes) sindex memory inuse: 0 (bytes) avail pct 100
    Mar 16 2015 06:32:15 GMT: INFO (info): (thr_info.c::4689)    partitions: actual 8192 sync 0 desync 0 zombie 0 wait 0 absent 0
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (1 total) msec
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: proxy (0 total) msec
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: writes_reply (1 total) msec
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::163)  (28: 0000000001)
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: udf (0 total) msec
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: query (0 total) msec
    Mar 16 2015 06:32:15 GMT: INFO (info): (hist.c::137) histogram dump: query_rec_count (0 total) count
    Mar 16 2015 06:32:18 GMT: INFO (paxos): (paxos.c::2522) as_paxos_retransmit_check: node bb9449b93d9bed4 retransmitting partition sync request to principal bb9ce179d56b1f8 ... 
    Mar 16 2015 06:32:18 GMT: INFO (paxos): (paxos.c::2232) Sent partition sync request to node bb9ce179d56b1f8