Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

consul 0.5.2 hangs on startup... #956

Closed
sean- opened this issue May 19, 2015 · 9 comments
Closed

consul 0.5.2 hangs on startup... #956

sean- opened this issue May 19, 2015 · 9 comments

Comments

@sean-
Copy link
Contributor

sean- commented May 19, 2015

I believe this issue is present in consul 0.5.1 as well. This was reported in the FreeBSD PR updating ports sysutils/consul to 0.5.1. Updating to 0.5.2 also seems to manifest the same problem.

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=200231

# cat run
#!/bin/sh --

set -e
exec /usr/local/sbin/chpst -e ./env \
    /usr/local/bin/consul agent -server \
        -config-dir=/var/service/consul/etc \
        -config-file=/var/service/consul/consul.conf.json \
        -data-dir=/var/consul \
        -node=consul01 \
        -log-level=trace
# sh run
==> Starting raft data migration...

It looks like /var/consul/raft/raft.db.temp is being written out and contains data, but for some reason Migrate is hanging.

# du -Ah /var/consul/raft/raft.db.temp
1.0M    /var/consul/raft/raft.db.temp

The process just hangs until terminated. Moving /var/consul/raft out of the way allowed for the process to start. After a minute or so, consul is in sync again:

[INFO] agent: Synced service 'consul'

I have not investigated exactly what the issue is yet, only that this workaround seems to work. My initial guess is that there is an assumption about the way lmdb and bolt are compatible, but this issue is mitigated by removing the raft directory and pulling the data over fresh from another server.
@armon
Copy link
Member

armon commented May 19, 2015

@sean- Can you tell if its hung or just migrating? Our own servers took like 90 seconds to finish the migration. Or did they just sit there forever?

/cc: @ryanuber any ideas why it would be hanging?

@ryanuber
Copy link
Member

That is interesting - the migration utility only uses the Raft interfaces, so I'm not sure where this might be stemming from. @sean- how large is the original LMDB data directory?

@armon
Copy link
Member

armon commented May 19, 2015

@ryanuber For the upgrade utility, can we have it output incremental process (e.g. 5%..10%...) so that it's clear something is happening at least?

@ryanuber
Copy link
Member

@armon, yeah I think we can update some counter after each raft log is converted over. I'll take a stab at that.

@sean-
Copy link
Contributor Author

sean- commented May 20, 2015

@armon the total size was ~1MB, it should have been tiny. I truss'ed the process and it was working, but not doing anything. It looked like it was spinning in place forever. I see it was opening have the truss logs available.

0.000054561 write(1,"==> Starting raft data migration"...,35) = 35 (0x23)
==> Starting raft data migration...55358: 0.000054561 write(1,"==> Starting raft data migration"...,35) = 35 (0x23)
55358: 0.000041493 clock_gettime(4,{3516242.439161507 }) = 0 (0x0)

55358: 0.000040021 write(1,"\n",1)               = 1 (0x1)
55358: 0.000020541 clock_gettime(0,{1432019585.793747324 }) = 0 (0x0)
55358: 0.000053395 _umtx_op(0xc2080520d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000640594 _umtx_op(0xc2080520d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000298770 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000023785 clock_gettime(0,{1432019585.794308040 }) = 0 (0x0)
55358: 0.000045430 stat("/var/groupon/consul/raft/mdb",{ mode=drwxr-xr-x ,inode=1544,size=4,blksize=16384 }) = 0 (0x0)
55358: 0.000191581 clock_gettime(4,{3516242.440191358 }) = 0 (0x0)
55358: 0.000017676 clock_gettime(4,{3516242.440495294 }) = 0 (0x0)
55358: 0.000017868 clock_gettime(0,{1432019585.794857232 }) = 0 (0x0)
55358: 0.000018532 _umtx_op(0xc20811c0d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000326205 _umtx_op(0xc20811c0d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000166857 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000023811 clock_gettime(4,{3516242.441170875 }) = 0 (0x0)
55358: 0.000016542 clock_gettime(0,{1432019585.795545867 }) = 0 (0x0)
55358: 0.000140258 clock_gettime(4,{3516242.441285603 }) = 0 (0x0)
55358: 0.000039428 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000039256 stat("/var/groupon/consul/raft/mdb",{ mode=drwxr-xr-x ,inode=1544,size=4,blksize=16384 }) = 0 (0x0)
55358: 0.000184483 clock_gettime(4,{3516242.441662279 }) = 0 (0x0)
55358: 0.000014559 clock_gettime(0,{1432019585.796177682 }) = 0 (0x0)
55358: 0.000017591 clock_gettime(4,{3516242.442102968 }) = 0 (0x0)
55358: 0.000157218 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000017711 clock_gettime(4,{3516242.442312028 }) = 0 (0x0)
55358: 0.000019424 clock_gettime(0,{1432019585.796672036 }) = 0 (0x0)
55358: 0.000043598 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000119965 clock_gettime(4,{3516242.442579119 }) = 0 (0x0)
55358: 0.000120218 clock_gettime(4,{3516242.442682536 }) = 0 (0x0)
55358: 0.000019719 clock_gettime(0,{1432019585.797144954 }) = 0 (0x0)
55358: 0.000044386 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000014570 clock_gettime(4,{3516242.443200629 }) = 0 (0x0)
55358: 0.000014669 clock_gettime(0,{1432019585.797544458 }) = 0 (0x0)
55358: 0.000020272 getpid()                      = 55358 (0xd83e)
55358: 0.000020711 __sysctl(0x7fffffffe538,0x2,0x7fffffffe534,0x7fffffffe540,0x0,0x0) = 0 (0x0)
55358: 0.000201346 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000019362 clock_gettime(4,{3516242.443835892 }) = 0 (0x0)
55358: 0.000015031 clock_gettime(0,{1432019585.798191117 }) = 0 (0x0)
55358: 0.000046311 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000014303 clock_gettime(4,{3516242.444230528 }) = 0 (0x0)
55358: 0.000017823 clock_gettime(0,{1432019585.798578274 }) = 0 (0x0)
55358: 0.000044461 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000014333 clock_gettime(4,{3516242.444624832 }) = 0 (0x0)
55358: 0.000014418 clock_gettime(0,{1432019585.798968428 }) = 0 (0x0)
55358: 0.000061127 openat(0xffffff9c,0x802036060,0x100202,0x1ed,0x10,0x18a2a) = 3 (0x3)
55358: 0.000264497 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000014472 clock_gettime(4,{3516242.445214604 }) = 0 (0x0)
55358: 0.000018565 clock_gettime(0,{1432019585.799560581 }) = 0 (0x0)
55358: 0.000025257 fcntl(3,F_SETLK,0x7fffffffe2d0) = 0 (0x0)
55358: 0.000019285 lseek(3,0x0,SEEK_END)         = 8192 (0x2000)
55358: 0.000154516 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000028980 mmap(0x0,8192,PROT_READ|PROT_WRITE,MAP_SHARED,3,0x0) = 34379862016 (0x801331000)
55358: 0.000014166 clock_gettime(4,{3516242.446013314 }) = 0 (0x0)
55358: 0.000013977 clock_gettime(0,{1432019585.800374397 }) = 0 (0x0)
55358: 0.000016980 fstat(3,{ mode=-rwxr-xr-x ,inode=1545,size=8192,blksize=8192 }) = 0 (0x0)
55358: 0.000138682 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000018069 clock_gettime(4,{3516242.446474535 }) = 0 (0x0)
55358: 0.000017955 clock_gettime(0,{1432019585.800834676 }) = 0 (0x0)
55358: 0.000161445 unlink("/tmp/SEMDMDBr%y8R9Gn0DT") = 0 (0x0)
55358: 0.000289520 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000109450 unlink("/tmp/SEMDMDBw%y8R9Gn0DT") = 0 (0x0)
55358: 0.000014271 clock_gettime(4,{3516242.447314156 }) = 0 (0x0)
55358: 0.000014791 clock_gettime(0,{1432019585.801675184 }) = 0 (0x0)
55358: 0.000043758 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000014576 clock_gettime(4,{3516242.447725679 }) = 0 (0x0)
55358: 0.000014515 clock_gettime(0,{1432019585.802087364 }) = 0 (0x0)
55358: 0.000084341 open("/tmp/SEMDMDBr%y8R9Gn0DT",O_RDWR|O_EXLOCK|O_CREAT|O_EXCL|O_CLOEXEC,0755) = 4 (0x4)
55358: 0.000242870 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000018322 clock_gettime(4,{3516242.448302284 }) = 0 (0x0)
55358: 0.000021458 fstat(4,{ mode=-rwxr-xr-x ,inode=1849,size=0,blksize=131072 }) = 0 (0x0)
55358: 0.000014463 clock_gettime(0,{1432019585.802782506 }) = 0 (0x0)
55358: 0.000045605 write(4,"1mes\0\0\0\0\^A\0\0\0\^C\0\0\0",16) = 16 (0x10)
55358: 0.000020149 flock(0x4,0x8,0x10,0xff53432f6d463851,0x101010101010101,0x8080808080808080) = 0 (0x0)
55358: 0.000203387 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000028632 mmap(0x0,16,PROT_READ|PROT_WRITE,MAP_SHARED|MAP_NOSYNC,4,0x0) = 34379870208 (0x801333000)
55358: 0.000014774 clock_gettime(4,{3516242.449366517 }) = 0 (0x0)
55358: 0.000016229 clock_gettime(0,{1432019585.803731662 }) = 0 (0x0)
55358: 0.000017859 close(4)                      = 0 (0x0)
55358: 0.000071967 open("/tmp/SEMDMDBw%y8R9Gn0DT",O_RDWR|O_EXLOCK|O_CREAT|O_EXCL|O_CLOEXEC,0755) = 4 (0x4)
55358: 0.000233452 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000020798 fstat(4,{ mode=-rwxr-xr-x ,inode=1850,size=0,blksize=131072 }) = 0 (0x0)
55358: 0.000014385 clock_gettime(4,{3516242.450197828 }) = 0 (0x0)
55358: 0.000045873 write(4,"1mes\0\0\0\0\^A\0\0\0\^C\0\0\0",16) = 16 (0x10)
55358: 0.000014301 clock_gettime(0,{1432019585.804748224 }) = 0 (0x0)
55358: 0.000020930 flock(0x4,0x8,0x10,0xff53432f6d463851,0x101010101010101,0x8080808080808080) = 0 (0x0)
55358: 0.000024380 mmap(0x0,16,PROT_READ|PROT_WRITE,MAP_SHARED|MAP_NOSYNC,4,0x0) = 34379874304 (0x801334000)
55358: 0.000204394 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000016719 clock_gettime(4,{3516242.451124844 }) = 0 (0x0)
55358: 0.000017974 close(4)                      = 0 (0x0)
55358: 0.000014266 clock_gettime(0,{1432019585.805593302 }) = 0 (0x0)
55358: 0.000065373 openat(0xffffff9c,0x802036086,0x202,0x1ed,0x4,0x18a2a) = 4 (0x4)
55358: 0.000022681 pread(0x4,0x7fffffffe4a8,0x98,0x0,0x4,0x18a2a) = 152 (0x98)
55358: 0.000200571 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000021348 pread(0x4,0x7fffffffe4a8,0x98,0x1000,0x4,0x18a2a) = 152 (0x98)
55358: 0.000017969 clock_gettime(4,{3516242.452193349 }) = 0 (0x0)
55358: 0.000047707 mmap(0x0,0,PROT_READ,MAP_SHARED,4,0x0) = 34401681408 (0x802800000)
55358: 0.000057327 openat(0xffffff9c,0x802036086,0x82,0x0,0x4,0x0) = 5 (0x5)
55358: 0.000255026 clock_gettime(0,{1432019585.806785766 }) = 0 (0x0)
55358: 0.000021144 fcntl(3,F_SETLK,0x7fffffffe540) = 0 (0x0)
55358: 0.000040609 nanosleep({0.000020000 })     = 0 (0x0)
55358: 0.000017777 clock_gettime(4,{3516242.453174783 }) = 0 (0x0)
55358: 0.000020195 clock_gettime(0,{1432019585.807536185 }) = 0 (0x0)
55358: 0.000018904 _umtx_op(0x801334004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000229608 nanosleep({0.000040000 })     = 0 (0x0)
55358: 0.000017754 clock_gettime(4,{3516242.453754433 }) = 0 (0x0)
55358: 0.000015041 clock_gettime(0,{1432019585.808112011 }) = 0 (0x0)
55358: 0.000016303 _umtx_op(0xc20811c0d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.012632317 _umtx_op(0xc20811c0d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000113014 open("/var/groupon/consul/raft/raft.db.temp",O_RDWR|O_CREAT|O_CLOEXEC,0600) = 6 (0x6)
55358: 0.000285567 nanosleep({0.000080000 })     = 0 (0x0)
55358: 0.000020955 clock_gettime(4,{3516242.454723537 }) = 0 (0x0)
55358: 0.000138040 clock_gettime(4,{3516242.454695986 }) = 0 (0x0)
55358: 0.000017633 clock_gettime(0,{1432019585.809209864 }) = 0 (0x0)
55358: 0.000017856 clock_gettime(0,{1432019585.809349065 }) = 0 (0x0)
55358: 0.000020980 flock(0x6,0x6,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000313010 nanosleep({0.000160000 })     = 0 (0x0)
55358: 0.000022233 fstat(6,{ mode=-rw------- ,inode=1698,size=0,blksize=16384 }) = 0 (0x0)
55358: 0.000014653 clock_gettime(4,{3516242.455604466 }) = 0 (0x0)
55358: 0.000014094 clock_gettime(0,{1432019585.809966274 }) = 0 (0x0)
55358: 0.000045271 pwrite(0x6,0xc208096000,0x4000,0x0,0x0,0x0) = 16384 (0x4000)
55358: 0.010590563 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.011015778 nanosleep({0.000320000 })     = 0 (0x0)
55358: 0.000019933 clock_gettime(4,{3516242.466975481 }) = 0 (0x0)
55358: 0.000023226 fstat(6,{ mode=-rw------- ,inode=1698,size=16384,blksize=16384 }) = 0 (0x0)
55358: 0.000014464 clock_gettime(0,{1432019585.821454193 }) = 0 (0x0)
55358: 0.000041995 ftruncate(6,1048576,0x0)      = 0 (0x0)
55358: 0.007488683 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.007672729 nanosleep({0.000640000 })     = 0 (0x0)
55358: 0.000030978 mmap(0x0,1048576,PROT_READ,MAP_SHARED,6,0x0) = 34386087936 (0x801921000)
55358: 0.000022383 clock_gettime(4,{3516242.475518557 }) = 0 (0x0)
55358: 0.000018077 clock_gettime(0,{1432019585.829884642 }) = 0 (0x0)
55358: 0.000020864 _umtx_op(0xc20811c0d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.021022586 _umtx_op(0xc20811c0d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000021405 clock_gettime(4,{3516242.476120194 }) = 0 (0x0)
55358: 0.000014994 clock_gettime(0,{1432019585.830571802 }) = 0 (0x0)
55358: 0.000019923 clock_gettime(0,{1432019585.830706473 }) = 0 (0x0)
55358: 0.000015792 clock_gettime(0,{1432019585.830841429 }) = 0 (0x0)
55358: 0.000014378 clock_gettime(0,{1432019585.830988550 }) = 0 (0x0)
55358: 0.000054958 pwrite(0x6,0xc20800f000,0x1000,0x4000,0x0,0x0) = 4096 (0x1000)
55358: 0.000033799 pwrite(0x6,0xc208102000,0x1000,0x5000,0x0,0x0) = 4096 (0x1000)
55358: 0.006190507 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.007734366 nanosleep({0.001280000 })     = 0 (0x0)
55358: 0.000045900 pwrite(0x6,0xc208103000,0x1000,0x0,0x0,0x0) = 4096 (0x1000)
55358: 0.007922542 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.008333665 clock_gettime(4,{3516242.483780241 }) = 0 (0x0)
55358: 0.000021294 clock_gettime(0,{1432019585.846450013 }) = 0 (0x0)
55358: 0.000021999 clock_gettime(0,{1432019585.846571642 }) = 0 (0x0)
55358: 0.000020916 fcntl(3,F_SETLK,0x7fffffffe4e0) = 0 (0x0)
55358: 0.000024610 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000020440 clock_gettime(0,{1432019585.847150786 }) = 0 (0x0)
55358: 0.000022676 clock_gettime(0,{1432019585.847291936 }) = 0 (0x0)
55358: 0.000021943 clock_gettime(4,{3516242.493195861 }) = 0 (0x0)
55358: 0.000019669 clock_gettime(0,{1432019585.847559411 }) = 0 (0x0)
55358: 0.000019946 clock_gettime(0,{1432019585.847692852 }) = 0 (0x0)
55358: 0.000052127 pwrite(0x6,0xc20812e000,0x1000,0x2000,0x0,0x0) = 4096 (0x1000)
55358: 0.000042054 pwrite(0x6,0xc20812f000,0x1000,0x3000,0x0,0x0) = 4096 (0x1000)
55358: 0.006280042 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.008061416 nanosleep({0.002560000 })     = 0 (0x0)
55358: 0.000022886 clock_gettime(4,{3516242.500632701 }) = 0 (0x0)
55358: 0.000017467 clock_gettime(0,{1432019585.854993416 }) = 0 (0x0)
55358: 0.000022363 clock_gettime(4,{3516242.500876754 }) = 0 (0x0)
55358: 0.024786001 _umtx_op(0xc20811c0d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000162028 _umtx_op(0xc20811c0d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000013954 clock_gettime(4,{3516242.501334791 }) = 0 (0x0)
55358: 0.000050359 pwrite(0x6,0xc208130000,0x1000,0x1000,0x0,0x0) = 4096 (0x1000)
55358: 0.007072975 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.007948924 nanosleep({0.005120000 })     = 0 (0x0)
55358: 0.000018519 clock_gettime(0,{1432019585.863275334 }) = 0 (0x0)
55358: 0.000021164 clock_gettime(4,{3516242.509150470 }) = 0 (0x0)
55358: 0.000022702 clock_gettime(0,{1432019585.863517156 }) = 0 (0x0)
55358: 0.000022480 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000022152 clock_gettime(0,{1432019585.863901400 }) = 0 (0x0)
55358: 0.000020407 clock_gettime(0,{1432019585.864022779 }) = 0 (0x0)
55358: 0.000021723 clock_gettime(0,{1432019585.864162655 }) = 0 (0x0)
55358: 0.000019441 clock_gettime(0,{1432019585.864291762 }) = 0 (0x0)
55358: 0.000050934 pwrite(0x6,0xc208131000,0x1000,0x4000,0x0,0x0) = 4096 (0x1000)
55358: 0.000040591 pwrite(0x6,0xc208132000,0x1000,0x5000,0x0,0x0) = 4096 (0x1000)
55358: 0.006576307 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000045170 pwrite(0x6,0xc208133000,0x1000,0x0,0x0,0x0) = 4096 (0x1000)
55358: 0.007998679 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.016395814 nanosleep({0.010000000 })     = 0 (0x0)
55358: 0.000022259 clock_gettime(0,{1432019585.880148533 }) = 0 (0x0)
55358: 0.000017156 clock_gettime(4,{3516242.526031819 }) = 0 (0x0)
55358: 0.000022483 clock_gettime(0,{1432019585.880385630 }) = 0 (0x0)
55358: 0.024881558 _umtx_op(0xc20811c0d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000191176 _umtx_op(0xc20811c0d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000151061 clock_gettime(4,{3516242.526469590 }) = 0 (0x0)
55358: 0.000025013 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000019927 clock_gettime(0,{1432019585.881187875 }) = 0 (0x0)
55358: 0.000019324 clock_gettime(0,{1432019585.881308306 }) = 0 (0x0)
55358: 0.000022547 clock_gettime(4,{3516242.527210574 }) = 0 (0x0)
55358: 0.000019029 clock_gettime(0,{1432019585.881574154 }) = 0 (0x0)
55358: 0.000019741 clock_gettime(0,{1432019585.881706395 }) = 0 (0x0)
55358: 0.000050347 pwrite(0x6,0xc208112000,0x1000,0x2000,0x0,0x0) = 4096 (0x1000)
55358: 0.000041758 pwrite(0x6,0xc208113000,0x1000,0x3000,0x0,0x0) = 4096 (0x1000)
55358: 0.005970004 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000022832 clock_gettime(4,{3516242.534236791 }) = 0 (0x0)
55358: 0.000043625 pwrite(0x6,0xc208114000,0x1000,0x1000,0x0,0x0) = 4096 (0x1000)
55358: 0.007877466 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.016363440 nanosleep({0.010000000 })     = 0 (0x0)
55358: 0.000018171 clock_gettime(0,{1432019585.896967668 }) = 0 (0x0)
55358: 0.000017263 clock_gettime(4,{3516242.542857448 }) = 0 (0x0)
55358: 0.000022835 clock_gettime(0,{1432019585.897213049 }) = 0 (0x0)
55358: 0.000022031 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000021693 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000022337 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000022436 clock_gettime(0,{1432019585.898042130 }) = 0 (0x0)
55358: 0.000022256 clock_gettime(0,{1432019585.898178088 }) = 0 (0x0)
55358: 0.000021914 clock_gettime(0,{1432019585.898321381 }) = 0 (0x0)
55358: 0.000019602 clock_gettime(0,{1432019585.898450690 }) = 0 (0x0)
55358: 0.000052596 pwrite(0x6,0xc208115000,0x1000,0x4000,0x0,0x0) = 4096 (0x1000)
55358: 0.000041251 pwrite(0x6,0xc208116000,0x1000,0x5000,0x0,0x0) = 4096 (0x1000)
55358: 0.006090671 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000047572 pwrite(0x6,0xc208117000,0x1000,0x0,0x0,0x0) = 4096 (0x1000)
55358: 0.008003064 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.016376519 nanosleep({0.010000000 })     = 0 (0x0)
55358: 0.000020789 clock_gettime(0,{1432019585.913834189 }) = 0 (0x0)
55358: 0.000017635 clock_gettime(4,{3516242.559715618 }) = 0 (0x0)
55358: 0.000017760 clock_gettime(0,{1432019585.914083930 }) = 0 (0x0)
55358: 0.033301611 _umtx_op(0xc20811c0d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000160921 _umtx_op(0xc20811c0d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000018431 clock_gettime(4,{3516242.560289969 }) = 0 (0x0)
55358: 0.000024489 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000018854 clock_gettime(0,{1432019585.914911291 }) = 0 (0x0)
55358: 0.000021980 clock_gettime(0,{1432019585.915054999 }) = 0 (0x0)
55358: 0.000022045 clock_gettime(4,{3516242.560956857 }) = 0 (0x0)
55358: 0.000021444 clock_gettime(0,{1432019585.915337934 }) = 0 (0x0)
55358: 0.000019714 clock_gettime(0,{1432019585.915468500 }) = 0 (0x0)
55358: 0.000052558 pwrite(0x6,0xc208144000,0x1000,0x2000,0x0,0x0) = 4096 (0x1000)
55358: 0.000041443 pwrite(0x6,0xc208145000,0x1000,0x3000,0x0,0x0) = 4096 (0x1000)

and this continues for a while, but then it stops and the output changes:

55358: 0.000057285 pwrite(0x6,0xc208191000,0x1000,0x1a000,0x0,0x0) = 4096 (0x1000)
55358: 0.000049520 pwrite(0x6,0xc20815a000,0x1000,0x1b000,0x0,0x0) = 4096 (0x1000)
55358: 0.000047408 pwrite(0x6,0xc20815b000,0x1000,0x1c000,0x0,0x0) = 4096 (0x1000)
55358: 0.000041502 pwrite(0x6,0xc20815c000,0x1000,0x1d000,0x0,0x0) = 4096 (0x1000)
55358: 0.005809656 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000052948 pwrite(0x6,0xc20815d000,0x1000,0x0,0x0,0x0) = 4096 (0x1000)
55358: 0.007940576 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.016361012 nanosleep({0.010000000 })     = 0 (0x0)
55358: 0.000127204 clock_gettime(0,{1432019612.288175998 }) = 0 (0x0)
55358: 0.000018343 clock_gettime(4,{3516268.934160619 }) = 0 (0x0)
55358: 0.000017616 clock_gettime(0,{1432019612.288512090 }) = 0 (0x0)
55358: 0.024664604 _umtx_op(0xc20809e0d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000208225 _umtx_op(0xc20809e0d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000179065 clock_gettime(4,{3516268.934612560 }) = 0 (0x0)
55358: 0.000029680 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000029559 clock_gettime(4,{3516268.935168597 }) = 0 (0x0)
55358: 0.000027190 clock_gettime(4,{3516268.935329444 }) = 0 (0x0)
55358: 0.000027075 clock_gettime(0,{1432019612.289715083 }) = 0 (0x0)
55358: 0.000026926 clock_gettime(0,{1432019612.289853469 }) = 0 (0x0)
55358: 0.000028440 clock_gettime(0,{1432019612.290043650 }) = 0 (0x0)
55358: 0.000029002 clock_gettime(4,{3516268.935947658 }) = 0 (0x0)
55358: 0.000027724 clock_gettime(0,{1432019612.290329387 }) = 0 (0x0)
55358: 0.000064377 pwrite(0x6,0xc2080d5000,0x1000,0x2000,0x0,0x0) = 4096 (0x1000)
55358: 0.000045640 pwrite(0x6,0xc2081e2000,0x1000,0x3000,0x0,0x0) = 4096 (0x1000)
55358: 0.000050840 pwrite(0x6,0xc2081e3000,0x1000,0x6000,0x0,0x0) = 4096 (0x1000)
55358: 0.000048123 pwrite(0x6,0xc2080d6000,0x1000,0xa000,0x0,0x0) = 4096 (0x1000)
55358: 0.004943148 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000059437 pwrite(0x6,0xc2080d7000,0x1000,0x1000,0x0,0x0) = 4096 (0x1000)
55358: 0.007947153 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)
55358: 0.016326997 nanosleep({0.010000000 })     = 0 (0x0)
55358: 0.000024482 clock_gettime(0,{1432019612.305068149 }) = 0 (0x0)
55358: 0.000017611 clock_gettime(4,{3516268.950968813 }) = 0 (0x0)
55358: 0.000024767 clock_gettime(0,{1432019612.305324542 }) = 0 (0x0)
55358: 0.000033670 _umtx_op(0x801333004,UMTX_OP_SEM_WAKE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000026479 clock_gettime(4,{3516268.951519381 }) = 0 (0x0)
55358: 0.000026850 clock_gettime(0,{1432019612.305930028 }) = 0 (0x0)
55358: 0.000026964 clock_gettime(0,{1432019612.306069099 }) = 0 (0x0)
55358: 0.000031206 clock_gettime(4,{3516268.952013612 }) = 0 (0x0)
55358: 0.000027143 clock_gettime(0,{1432019612.306404534 }) = 0 (0x0)
55358: 0.000027704 clock_gettime(4,{3516268.952308496 }) = 0 (0x0)
55358: 0.000027487 clock_gettime(4,{3516268.952479388 }) = 0 (0x0)
55358: 0.017802932 _umtx_op(0xc20809e0d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000177288 _umtx_op(0xc20809e0d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000028177 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000246020 _umtx_op(0xc20802cb58,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.125234679 _umtx_op(0xc20802cb58,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000314548 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000016567 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000031472 _umtx_op(0xc20802c458,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.128120642 _umtx_op(0xc20802c458,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000025504 _umtx_op(0xc20802d958,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.204062557 _umtx_op(0xc20802d958,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.209803819 _umtx_op(0x1163d98,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000912394 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000355531 _umtx_op(0x1163d98,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000039363 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000046575 _umtx_op(0xc20809e458,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.210445148 _umtx_op(0xc20809e458,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000042401 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000046210 _umtx_op(0xc208052b58,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.213160985 _umtx_op(0xc208052b58,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000044882 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000035000 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000033958 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000050773 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000054374 _umtx_op(0xc208053258,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000050731 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000038200 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.214919768 _umtx_op(0xc208053258,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000049708 _umtx_op(0xc20811d958,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000046733 sched_yield(0x0,0xc2080500c0,0x7fffffffffff,0xc207ffaff3,0x0,0xc208000000) = 0 (0x0)
55358: 0.214744912 _umtx_op(0xc20811d958,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000212764 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000061222 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000056620 sched_yield(0xc20802c458,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000036599 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.217089529 _umtx_op(0xc2080535d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000344816 sched_yield(0x0,0xc2080500c0,0x7fffffffffff,0xc207ffaff3,0x0,0xc208000000) = 0 (0x0)
55358: 0.000510083 _umtx_op(0xc2080535d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000074116 _umtx_op(0xc20802dcd8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.218074318 _umtx_op(0xc20802dcd8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000727754 sched_yield(0x0,0xc208051380,0x7fffffffffff,0xc207ffaec7,0x0,0xc208000000) = 0 (0x0)
55358: 0.000056644 sched_yield(0xc20802c458,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000045323 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000051073 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000050716 sched_yield(0xc20809e0d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.010866472 nanosleep({0.010000000 })     = 0 (0x0)
55358: 0.000064371 sched_yield(0xc20802c458,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000060547 sched_yield(0x0,0xc208051380,0x7fffffffffff,0xc207ffaec7,0x0,0xc208000000) = 0 (0x0)
55358: 0.000051772 _umtx_op(0xc2080520d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.220621583 _umtx_op(0xc2080520d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000069784 _umtx_op(0xc20811d5d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000073548 _umtx_op(0xc20811d258,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.221414164 _umtx_op(0xc20811d5d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000074138 sched_yield(0x7fffdfffdea0,0x0,0x0,0x0,0x7fffdfffde10,0x18d3f) = 0 (0x0)
55358: 0.001222209 nanosleep({0.000100000 })     = 0 (0x0)
55358: 0.000067208 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.222043321 _umtx_op(0xc20811d258,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000082736 sched_yield(0x1163d98,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.222640506 _umtx_op(0xc20802ced8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.001444329 _umtx_op(0xc20802ced8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.002585280 sched_yield(0x0,0xc2080500c0,0x7fffffffffff,0xc207ffaff3,0x0,0xc208000000) = 0 (0x0)
55358: 0.224257658 _umtx_op(0xc20809e7d8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000307311 _umtx_op(0xc20809e7d8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.000081754 sched_yield(0x0,0xc208051380,0x7fffffffffff,0xc207ffaec7,0x0,0xc208000000) = 0 (0x0)
55358: 0.000060132 sched_yield(0xc20811d5d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000056213 sched_yield(0x7fffdebf3d08,0xda8218,0x7fffffffffff,0x195290,0x0,0xc208000000) = 0 (0x0)
55358: 0.000875891 nanosleep({0.000100000 })     = 0 (0x0)
55358: 0.000224361 nanosleep({0.000100000 })     = 0 (0x0)
55358: 0.000074835 sched_yield(0x0,0xc208051380,0x7fffffffffff,0xc207ffaec7,0x0,0xc208000000) = 0 (0x0)
55358: 0.000768131 sched_yield(0xc208053258,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000078911 sched_yield(0xc20811d958,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000081706 sched_yield(0x7fffdebf3d08,0xda8218,0x7fffffffffff,0x195290,0x0,0xc208000000) = 0 (0x0)
55358: 0.000783700 sched_yield(0x7fffdd5e8d10,0xda8218,0x7fffffffffff,0x195290,0x0,0xc208000000) = 0 (0x0)
55358: 0.000066021 sched_yield(0xc208053258,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000094236 sched_yield(0xc20811d5d8,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000085874 sched_yield(0x7fffdd5e8d10,0xda8218,0x7fffffffffff,0x195290,0x0,0xc208000000) = 0 (0x0)
55358: 0.000073964 sched_yield(0xc20802c458,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.001003929 sched_yield(0x0,0xc208051380,0x7fffffffffff,0xc207ffaec7,0x0,0xc208000000) = 0 (0x0)
55358: 0.000079213 _umtx_op(0xc208052ed8,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.229169680 _umtx_op(0xc208052ed8,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.003156999 nanosleep({0.000100000 })     = 0 (0x0)
55358: 0.000060833 sched_yield(0x7fffdebf3d08,0xda8218,0x0,0x195290,0x0,0xc208000000) = 0 (0x0)
55358: 0.000343083 sched_yield(0x7fffdd5e8d10,0xda8218,0x7fffffffffff,0x195290,0x0,0xc208000000) = 0 (0x0)
55358: 0.000078693 sched_yield(0xc208053258,0xf,0x7fffffffffff,0x0,0x0,0xc208000000) = 0 (0x0)
55358: 0.000081101 sched_yield(0x80119da18,0x80119ca38,0x7fffffffffff,0xc207ffd577,0x0,0xc208000000) = 0 (0x0)
55358: 0.000092236 sched_yield(0x0,0xc2080a2240,0x7fffffffffff,0xc207ff5ddb,0x0,0xc208000000) = 0 (0x0)
55358: 0.004649973 sched_yield(0x0,0xc2080500c0,0x7fffffffffff,0xc207ffaff3,0x0,0xc208000000) = 0 (0x0)
55358: 0.000075343 sched_yield(0x0,0xc20805e750,0x7fffffffffff,0xc207ffa18a,0x0,0xc208000000) = 0 (0x0)
55358: 0.000093387 sched_yield(0x0,0xc208052a80,0x7fffffffffff,0xc207ffad57,0x0,0xc208000000) = 0 (0x0)
55358: 0.000065925 _umtx_op(0xc20811cb58,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.232346589 _umtx_op(0xc20811cb58,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.000068993 sched_yield(0x0,0xc2080a2240,0x7fffffffffff,0xc207ff5ddb,0x0,0xc208000000) = 0 (0x0)
55358: 0.001120557 sched_yield(0x0,0xc2080f4000,0x7fffffffffff,0xc207ff0bff,0x0,0xc208000000) = 0 (0x0)
55358: 0.000108169 sched_yield(0x4,0xc208068008,0x7fffffffffff,0xc207ff97ff,0x0,0xc208000000) = 0 (0x0)
55358: 0.000080396 sched_yield(0x0,0xc208051380,0x7fffffffffff,0xc207ffaec7,0x0,0xc208000000) = 0 (0x0)
55358: 0.000100660 sched_yield(0x0,0xc2080a2240,0x7fffffffffff,0xc207ff5ddb,0x0,0xc208000000) = 0 (0x0)
55358: 0.000097224 sched_yield(0x0,0xc208051380,0x7fffffffffff,0xc207ffaec7,0x0,0xc208000000) = 0 (0x0)
55358: 0.000083696 sched_yield(0x0,0xc208052a80,0x7fffffffffff,0xc207ffad57,0x0,0xc208000000) = 0 (0x0)
55358: 0.000070688 _umtx_op(0xc20809eb58,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
55358: 0.235816701 _umtx_op(0xc20809eb58,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
55358: 0.002343238 sched_yield(0x0,0xc208086dc0,0x7fffffffffff,0xc207ff7923,0x0,0xc208000000) = 0 (0x0)
55358: 0.001762141 sched_yield(0x0,0xc208036d70,0x7fffffffffff,0xc207ffc928,0x0,0xc208000000) = 0 (0x0)
55358: 0.000095324 sched_yield(0x0,0xc208052a80,0x7fffffffffff,0xc207ffad57,0x0,0xc208000000) = 0 (0x0)
55358: 0.000077931 sched_yield(0x0,0xc208036d70,0x7fffffffffff,0xc207ffc928,0x0,0xc208000000) = 0 (0x0)

And the process basically loops forever. I still haven't chased this in to code, but this is what I recorded before employing the workaround.

@ryanuber
Copy link
Member

Yeah this definitely sounds like a problem - 1MB should have flown through very quickly. I've added progress indication to Consul's master branch, which might help to understand which phase the migration hangs at. It will dump some output like this:

==> Starting raft data migration...
==> Migrating stable store
    0.00%
    33.33%
    66.67%
    100.00%
==> Migrating log store
    0.00%
    6.67%
    13.33%
    20.00%
    26.67%
    33.33%
    40.00%
    46.67%
    53.33%
    60.00%
    66.67%
    73.33%
    80.00%
    86.67%
    93.33%
    100.00%
==> Moving Bolt file into place
    0.00%
    100.00%
==> Archiving LMDB data
    0.00%
    100.00%
==> Successfully migrated raft data in 13.626374ms

@sean- correct me if I'm wrong, but it looks like you are using FreeBSD? In the meantime, I'm going to set up a FreeBSD machine and give the migrator a test.

@sean-
Copy link
Contributor Author

sean- commented May 20, 2015

I still have the raft directory kicking around but I've updated everything else though I'm sure I could reproduce this. I actually am wondering if there is a race condition someplace because it looks like Go is polling when it enters this hung state. And actually, if I had to guess, it's that there is race condition or something is not having lmdb close its database correctly. I don't see any close(2) calls after the 4096B writes from lmdb are complete.

Also:

55358: 0.000041502 pwrite(0x6,0xc20815c000,0x1000,0x1d000,0x0,0x0) = 4096 (0x1000)
55358: 0.005809656 fsync(0x6,0x0,0x0,0x0,0x0,0x0) = 0 (0x0)

The above logs were generated via truss -D, so the second column is seconds since the previous syscall(2) which means these pwrite(2) and fsync(2) calls are finishing in 41.5us and 5.8ms, respectively. LMAO if there's a race condition because AWS doesn't normally expose low latency writes to applications or test environments. grin

@sean-
Copy link
Contributor Author

sean- commented May 20, 2015

Looking through consul-migrator and the above truss output, my semi-educated guess would be to look here for a loop:

https://github.com/hashicorp/consul-migrate/blob/master/migrator/migrator.go#L126

I'm seeing the unlink of the temp file, but not seeing the output from

return false, fmt.Errorf("Failed to migrate stable store: %v", err)

at https://github.com/hashicorp/consul-migrate/blob/master/migrator/migrator.go#L244

@slackpad
Copy link
Contributor

Now that we've removed auto-migration I'm going to close this one out.

@ekmixon ekmixon mentioned this issue Jun 23, 2023
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@sean- @armon @slackpad @ryanuber