Death flock on .hhvm.hhbc

GreenRover commented 9 years ago

Hello, i have server with sever cron jobs runing by hhvm.

After a couple of hours, one process dont gives the flock on .hhvm.hhbc free.

HipHop VM 3.6.0-dev (rel)
Compiler: heads/master-0-g8fa595dcc71ba2de63fb73b15e61dc9fd50a0971
Repo schema: d8ec4ce9760f167994ab9f19161c09a7534ff14f

Here a strace ofa new process

fstat(4, {st_mode=S_IFREG|0644, st_size=92, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6a72f35000
read(4, "# The \"order\" line is only used "..., 4096) = 92
read(4, "", 4096)                       = 0
close(4)                                = 0
munmap(0x7f6a72f35000, 4096)            = 0
futex(0x7f6a6bbea3d0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
lseek(3, 0, SEEK_SET)                   = 0
read(3, "127.0.0.1\tlocalhost\n127.0.1.1\tpo"..., 4096) = 246
read(3, "", 4096)                       = 0
uname({sys="Linux", node="portal3-demo", ...}) = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=19, ...}) = 0
lseek(3, 0, SEEK_SET)                   = 0
read(3, "127.0.0.1\tlocalhost\n127.0.1.1\tpo"..., 4096) = 246
read(3, "", 4096)                       = 0
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=58633, ...}) = 0
mmap(NULL, 58633, PROT_READ, MAP_PRIVATE, 4, 0) = 0x7f6a72eca000
close(4)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 4
read(4, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\21\0\0\0\0\0\0"..., 832) = 832
fstat(4, {st_mode=S_IFREG|0644, st_size=22952, ...}) = 0
mmap(NULL, 2117896, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0x7f6a603ed000
mprotect(0x7f6a603f2000, 2093056, PROT_NONE) = 0
mmap(0x7f6a605f1000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x4000) = 0x7f6a605f1000
close(4)                                = 0
mprotect(0x7f6a605f1000, 4096, PROT_READ) = 0
munmap(0x7f6a72eca000, 58633)           = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=19, ...}) = 0
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 4
connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 16) = 0
poll([{fd=4, events=POLLOUT}], 1, 0)    = 1 ([{fd=4, revents=POLLOUT}])
sendto(4, "\rU\1\0\0\1\0\0\0\0\0\0\fportal3-demo\0\0\34\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30
poll([{fd=4, events=POLLIN}], 1, 5000)  = 1 ([{fd=4, revents=POLLIN}])
ioctl(4, FIONREAD, [105])               = 0
recvfrom(4, "\rU\201\203\0\1\0\0\0\1\0\0\fportal3-demo\0\0\34\0\1\0\0"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 105
close(4)                                = 0
rt_sigaction(SIGQUIT, {0x8b1e80, [QUIT], SA_RESTORER|SA_RESTART, 0x7f6a6b85cd40}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGILL, {0x8b1e80, [ILL], SA_RESTORER|SA_RESTART, 0x7f6a6b85cd40}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGFPE, {0x8b1e80, [FPE], SA_RESTORER|SA_RESTART, 0x7f6a6b85cd40}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGSEGV, {0x8b1e80, [SEGV], SA_RESTORER|SA_RESTART, 0x7f6a6b85cd40}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGBUS, {0x8b1e80, [BUS], SA_RESTORER|SA_RESTART, 0x7f6a6b85cd40}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGABRT, {0x8b1e80, [ABRT], SA_RESTORER|SA_RESTART, 0x7f6a6b85cd40}, {SIG_DFL, [], 0}, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
open("/proc/self/maps", O_RDONLY|O_CLOEXEC) = 4
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
fstat(4, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6a72f35000
read(4, "00400000-02bcd000 r-xp 00000000 "..., 1024) = 1024
read(4, "   /lib/x86_64-linux-gnu/libnss_"..., 1024) = 1024
read(4, "7000 fc:00 786761               "..., 1024) = 1024
read(4, " /usr/lib/x86_64-linux-gnu/libhx"..., 1024) = 1024
read(4, "ibwind.so.0.0.0\n7f6a64684000-7f6"..., 1024) = 1024
read(4, "inux-gnu/libXdmcp.so.6.0.0\n7f6a6"..., 1024) = 1024
read(4, "          /usr/lib/x86_64-linux-"..., 1024) = 1024
read(4, "xp 00000000 fc:00 788245        "..., 1024) = 1024
read(4, "          /usr/lib/x86_64-linux-"..., 1024) = 1024
read(4, "-gnu/libgpg-error.so.0.10.0\n7f6a"..., 1024) = 1024
read(4, "        /usr/lib/x86_64-linux-gn"..., 1024) = 1024
read(4, "0 fc:00 788767                  "..., 1024) = 1024
read(4, "0 fc:00 68                      "..., 1024) = 1024
read(4, "ib/x86_64-linux-gnu/libunwind.so"..., 1024) = 1024
read(4, "7f6a67494000 rwxp 00028000 fc:00"..., 1024) = 1024
read(4, "00 787723                     /u"..., 1024) = 1024
read(4, "4-linux-gnu/libgcrypt.so.11.8.2\n"..., 1024) = 1024
read(4, "nu/libidn.so.11.6.11\n7f6a6829700"..., 1024) = 1024
read(4, "       /usr/lib/x86_64-linux-gnu"..., 1024) = 1024
read(4, "fc:00 950                       "..., 1024) = 1024
read(4, "xp 00011000 fc:00 792058        "..., 1024) = 1024
read(4, "u/libfftw3.so.3.3.2\n7f6a6ae75000"..., 1024) = 1024
read(4, "     /usr/lib/x86_64-linux-gnu/l"..., 1024) = 1024
read(4, "             /lib/x86_64-linux-g"..., 1024) = 1024
read(4, "             /lib/x86_64-linux-g"..., 1024) = 1024
read(4, "9.so\n7f6a6c626000-7f6a6c62a000 r"..., 1024) = 1024
read(4, "x86_64-linux-gnu/libboost_system"..., 1024) = 1024
read(4, "b000 r-xp 00000000 fc:00 790286 "..., 1024) = 1024
read(4, "nu/libcrypt-2.19.so\n7f6a6d2d3000"..., 1024) = 1024
read(4, "0-7f6a6d943000 ---p 0000d000 fc:"..., 1024) = 1024
read(4, "00 fc:00 801455                 "..., 1024) = 1024
read(4, "/lib/x86_64-linux-gnu/libexpat.s"..., 1024) = 1024
read(4, "0 787221                     /us"..., 1024) = 1024
read(4, "6a6ec3b000-7f6a6ee3a000 ---p 000"..., 1024) = 1024
read(4, "4-linux-gnu/libssl.so.1.0.0\n7f6a"..., 1024) = 1024
read(4, "-2.0.so.5.1.9\n7f6a6f8eb000-7f6a6"..., 1024) = 1024
read(4, "st_program_options.so.1.54.0\n7f6"..., 1024) = 1024
read(4, "000-7f6a701bd000 rwxp 00018000 f"..., 1024) = 1024
read(4, "86_64-linux-gnu/libcurl.so.4.3.0"..., 1024) = 1024
read(4, "dab000-7f6a70dac000 rwxp 0000000"..., 1024) = 1024
read(4, "7f6a714e7000-7f6a715e8000 r-xp 0"..., 1024) = 1024
read(4, "  /usr/lib/x86_64-linux-gnu/libv"..., 1024) = 1024
read(4, "7f6a722df000 r-xp 00043000 fc:00"..., 1024) = 1024
read(4, "u/libMagickWand.so.5.0.0\n7f6a72a"..., 1024) = 1024
read(4, "nux-gnu/ld-2.19.so\n7f6a72f3a000-"..., 1024) = 419
close(4)                                = 0
munmap(0x7f6a72f35000, 4096)            = 0
sched_getaffinity(13325, 32, {3, 0, 0, 0}) = 32
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
rt_sigaction(SIGVTALRM, {0x848230, [], SA_RESTORER|SA_NODEFER|SA_SIGINFO, 0x7f6a6c41c340}, NULL, 8) = 0
uname({sys="Linux", node="portal3-demo", ...}) = 0
getcwd("/root", 4096)                   = 6
gettid()                                = 13325
timer_create(CLOCK_REALTIME, {0x7f6a63347608, SIGVTALRM, SIGEV_SIGNAL, {...}}, {0}) = 0
timer_settime(0, 0, {it_interval={0, 0}, it_value={0, 0}}, {it_interval={0, 0}, it_value={0, 0}}) = 0
timer_settime(0, 0, {it_interval={0, 0}, it_value={90000, 0}}, NULL) = 0
open("/tmp/tcHvgZwF", O_RDWR|O_CREAT|O_EXCL, 0600) = 4
unlink("/tmp/tcHvgZwF")                 = 0
ftruncate(4, 16777216)                  = 0
mmap(NULL, 67108864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6a5c3ed000
mmap(0x7f6a5f3ed000, 16777216, PROT_READ|PROT_WRITE, MAP_SHARED|MAP_FIXED, 4, 0) = 0x7f6a5f3ed000
mmap(NULL, 524288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6a72e59000
readlink("/proc/self/exe", "/usr/bin/hhvm", 4096) = 13
readlink("/proc/self/exe", "/usr/bin/hhvm", 4096) = 13
uname({sys="Linux", node="portal3-demo", ...}) = 0
madvise(0x7f6a63034000, 3149824, MADV_DONTNEED) = 0
futex(0x7f6a6ea126a8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
brk(0x11000000)                         = 0x11000000
mprotect(0x4400000, 197132288, PROT_READ|PROT_WRITE|PROT_EXEC) = 0
open("/tmp/perf-13325.map", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5
readlink("/proc/self/exe", "/usr/bin/hhvm", 4096) = 13
open("/usr/bin/hhvm", O_RDONLY)         = 6
fcntl(6, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
pread(6, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\2\0>\0\1\0\0\0\340\352}\0\0\0\0\0"..., 64, 0) = 64
pread(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 9984, 48050376) = 9984
pread(6, "\0.symtab\0.strtab\0.shstrtab\0.inte"..., 2356, 48048014) = 2356
close(6)                                = 0
open("/usr/bin/hhvm", O_RDONLY)         = 6
lseek(6, 47543694, SEEK_SET)            = 47543694
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6a5bfed000
munmap(0x7f6a5bfed000, 4194304)         = 0
mmap(NULL, 8384512, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6a5bbee000
munmap(0x7f6a5bbee000, 73728)           = 0
munmap(0x7f6a5c000000, 4116480)         = 0
read(6, "<?hh\n// {@}generated\n\nnamespace "..., 504320) = 504320
close(6)                                = 0
stat("/var/www/.hhvm.hhbc", {st_mode=S_IFREG|0644, st_size=29316096, ...}) = 0
open("/var/www/.hhvm.hhbc", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 6
fstat(6, {st_mode=S_IFREG|0644, st_size=29316096, ...}) = 0
lseek(6, 0, SEEK_SET)                   = 0
read(6, "SQLite format 3\0\4\0\1\1\0@  \0\2)x\0\0o\325"..., 100) = 100
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 0}, NULL)                 = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 1000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 2000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 3000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 4000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 5000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 6000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 7000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 8000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 9000000}, NULL)           = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 10000000}, NULL)          = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 11000000}, NULL)          = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 12000000}, NULL)          = 0
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)

A lsof to see the lock

lsof | grep hhvm.hhbc
hhvm        668       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        668       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        668       www-data   23u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        669       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        669       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        669       www-data   24u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        670       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        670       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        670       www-data   25u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        776       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm        777       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1174       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1174       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1174       www-data   26u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1175       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1175       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1175       www-data   27u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1176       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1176       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1176       www-data   28u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1252       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1252       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1253       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1254       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1330       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1335       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       1341       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3540       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3540       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3540       www-data   29u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3541       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3541       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3541       www-data   30u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3542       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3542       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3542       www-data   31u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3600       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3601       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3891       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3891       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3891       www-data   32u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3892       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3892       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3892       www-data   33u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3893       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3893       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3893       www-data   34u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3978       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       3980       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4291       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4291       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4291       www-data   35u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4292       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4292       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4292       www-data   36u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4325       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4325       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4325       www-data   37u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4326       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4326       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4326       www-data   38u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4327       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4327       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4327       www-data   39u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4389       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4403       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4715       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4715       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4715       www-data   40u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4716       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4716       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4716       www-data   41u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4717       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4717       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4717       www-data   42u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4769       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       4771       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5131       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5131       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5131       www-data   43u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5132       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5132       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5132       www-data   44u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5133       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5133       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5133       www-data   45u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5196       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5197       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5485       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5485       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5485       www-data   46u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5486       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5486       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5486       www-data   47u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5487       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5487       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5487       www-data   48u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5548       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5551       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       5552       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7742       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7742       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7742       www-data   49u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7743       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7743       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7743       www-data   50u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7744       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7744       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7744       www-data   51u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7793       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       7797       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8080       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8080       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8080       www-data   52u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8081       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8081       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8081       www-data   53u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8082       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8082       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8082       www-data   54u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8165       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8170       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8529       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8529       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8529       www-data   55u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8530       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8530       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8530       www-data   56u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8531       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8531       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8531       www-data   57u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8586       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8591       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8899       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8899       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8899       www-data   58u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8900       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8900       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8900       www-data   59u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8901       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8901       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8901       www-data   60u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8963       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       8972       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9315       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9315       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9315       www-data   61u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9316       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9316       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9316       www-data   62u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9317       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9317       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9317       www-data   63u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9379       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9381       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9670       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9670       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9670       www-data   64u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9671       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9671       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9671       www-data   65u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9672       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9672       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9672       www-data   66u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9730       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9743       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm       9744       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10631       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10631       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10631       www-data   67u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10632       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10632       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10632       www-data   68u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10633       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10633       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10633       www-data   69u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10676       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      10679       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12324       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12324       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12324       www-data   70u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12325       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12325       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12325       www-data   71u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12326       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12326       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12326       www-data   72u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12409       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12413       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12756       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12756       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12756       www-data   73u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12757       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12757       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12757       www-data   74u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12758       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12758       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12758       www-data   75u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12830       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      12832       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13145       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13145       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13145       www-data   76u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13146       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13146       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13146       www-data   77u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13147       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13147       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13147       www-data   78u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13336       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      13342       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      30994       www-data    6ur     REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      30994       www-data   10ur     REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      30994       www-data   13ur     REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31169       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31169       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31170       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31170       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31171       www-data    6uw     REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31171       www-data    9uw     REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31171       www-data   10uw     REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31171       www-data   12u      REG              252,0     1544 276442 /var/www/.hhvm.hhbc-journal
hhvm      31329       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31329       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31329       www-data   14u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31330       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31330       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31330       www-data   15u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31331       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31331       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31331       www-data   16u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31457       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31462       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31743       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31743       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31743       www-data   17u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31744       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31744       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31744       www-data   18u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31745       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31745       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31745       www-data   19u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31829       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      31838       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32203       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32203       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32203       www-data   20u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32204       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32204       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32204       www-data   21u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32205       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32205       www-data    9u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32205       www-data   22u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32314       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc
hhvm      32320       www-data    6u      REG              252,0 29316096 284931 /var/www/.hhvm.hhbc

The strace of the process having the lock

Strace of prcess: 31171

strace -p 31171
Process 31171 attached
restart_syscall(<... resuming interrupted call ...>) = 0
nanosleep({3, 576000000}, NULL)         = 0
nanosleep({3, 577000000}, NULL)         = 0
nanosleep({3, 578000000}, NULL)         = 0
nanosleep({3, 579000000}, NULL)         = 0
nanosleep({3, 580000000}, NULL)         = 0
nanosleep({3, 581000000}, NULL)         = 0
nanosleep({3, 582000000}, NULL)         = 0
nanosleep({3, 583000000},

ps from this process

www-data 30994  0.0  1.5 662924 94356 ?        S    06:35   0:03  |       \_ /usr/bin/hhvm -c /etc/hhvm/php.ini /var/www/portal3/cli.php energymanager_importTrendData --mpm --fast_run
www-data 31169  0.0  1.1 646540 71012 ?        S    06:35   0:00  |           \_ /usr/bin/hhvm -c /etc/hhvm/php.ini /var/www/portal3/cli.php energymanager_importTrendData --mpm --fast_run
www-data 31170  0.0  1.1 646540 71132 ?        S    06:35   0:00  |           \_ /usr/bin/hhvm -c /etc/hhvm/php.ini /var/www/portal3/cli.php energymanager_importTrendData --mpm --fast_run
www-data 31171  0.0  1.1 646540 70344 ?        S    06:35   0:00  |           \_ /usr/bin/hhvm -c /etc/hhvm/php.ini /var/www/portal3/cli.php energymanager_importTrendData --mpm --fast_run

How can i provide more usefull data? I am actualy not able to reproduce this issue. Only by let the server run a couple of hours.

GreenRover commented 9 years ago

It seams 2 process try to get flock at the same time

hhvm      31171       www-data    6uw
hhvm      30994       www-data    6ur

Kill process 30994 will sove the issue for the moment. 31171 is a forked child of 30994 (php: pcntl_fork)

GreenRover commented 9 years ago

lsof | grep "/var/www/.hhvm.hhbc" | grep 'ur\|uw'
hhvm      24196       www-data    6ur     REG              252,0  29359104     284931 /var/www/.hhvm.hhbc
hhvm      24196       www-data   10ur     REG              252,0  29359104     284931 /var/www/.hhvm.hhbc
hhvm      24196       www-data   13ur     REG              252,0  29359104     284931 /var/www/.hhvm.hhbc
hhvm      24387       www-data    6uw     REG              252,0  29359104     284931 /var/www/.hhvm.hhbc
hhvm      24387       www-data    9uw     REG              252,0  29359104     284931 /var/www/.hhvm.hhbc
hhvm      24387       www-data   10uw     REG              252,0  29359104     284931 /var/www/.hhvm.hhbc
hhvm      24387       www-data   12u      REG              252,0      1544     265587 /var/www/.hhvm.hhbc-journal

strace -p 24196 
Process 24196 attached
restart_syscall(<... resuming interrupted call ...>) = 0
access("/var/www/.hhvm.hhbc-journal", F_OK) = 0
stat("/var/www/.hhvm.hhbc-journal", {st_mode=S_IFREG|0644, st_size=1544, ...}) = 0
fcntl(13, F_GETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741824, len=2, pid=24387}) = 0
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
lseek(13, 24, SEEK_SET)                 = 24
read(13, "\0\2B\374\0\0o\377\0\0\0\0\0\0\0\0", 16) = 16
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
access("/var/www/.hhvm.hhbc-wal", F_OK) = -1 ENOENT (No such file or directory)
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
fcntl(13, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741825, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({1, 433000000}, NULL)         = 0
access("/var/www/.hhvm.hhbc-journal", F_OK) = 0
stat("/var/www/.hhvm.hhbc-journal", {st_mode=S_IFREG|0644, st_size=1544, ...}) = 0
fcntl(13, F_GETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741824, len=2, pid=24387}) = 0
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
lseek(13, 24, SEEK_SET)                 = 24
read(13, "\0\2B\374\0\0o\377\0\0\0\0\0\0\0\0", 16) = 16
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
access("/var/www/.hhvm.hhbc-wal", F_OK) = -1 ENOENT (No such file or directory)
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
fcntl(13, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741825, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({1, 434000000}, NULL)         = 0
access("/var/www/.hhvm.hhbc-journal", F_OK) = 0
stat("/var/www/.hhvm.hhbc-journal", {st_mode=S_IFREG|0644, st_size=1544, ...}) = 0
fcntl(13, F_GETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741824, len=2, pid=24387}) = 0
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
lseek(13, 24, SEEK_SET)                 = 24
read(13, "\0\2B\374\0\0o\377\0\0\0\0\0\0\0\0", 16) = 16
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
access("/var/www/.hhvm.hhbc-wal", F_OK) = -1 ENOENT (No such file or directory)
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
fcntl(13, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741825, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({1, 435000000}, NULL)         = 0
access("/var/www/.hhvm.hhbc-journal", F_OK) = 0
stat("/var/www/.hhvm.hhbc-journal", {st_mode=S_IFREG|0644, st_size=1544, ...}) = 0
fcntl(13, F_GETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741824, len=2, pid=24387}) = 0
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
lseek(13, 24, SEEK_SET)                 = 24
read(13, "\0\2B\374\0\0o\377\0\0\0\0\0\0\0\0", 16) = 16
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
access("/var/www/.hhvm.hhbc-wal", F_OK) = -1 ENOENT (No such file or directory)
fstat(13, {st_mode=S_IFREG|0644, st_size=29359104, ...}) = 0
fcntl(13, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741825, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({1, 436000000}, ^CProcess 24196 detached
 <detached ...>

strace -p 24387
Process 24387 attached
restart_syscall(<... resuming interrupted call ...>) = 0
nanosleep({1, 526000000}, NULL)         = 0
nanosleep({1, 527000000}, NULL)         = 0
nanosleep({1, 528000000}, NULL)         = 0
nanosleep({1, 529000000}, NULL)         = 0
nanosleep({1, 530000000}, NULL)         = 0
nanosleep({1, 531000000}, NULL)         = 0
nanosleep({1, 532000000}, NULL)         = 0
nanosleep({1, 533000000}, ^CProcess 24387 detached
 <detached ...>

GreenRover commented 9 years ago

It seams to be a problem of sqllite http://stackoverflow.com/questions/20969996/is-it-safe-to-delete-sqlites-wal-file

Is it planed to use a real DBMS insted of sqlite?

paulbiss commented 9 years ago

I'm not aware of any such plans. Migrating to a full-fledged DBMS seems like overkill for this.

GreenRover commented 9 years ago

How would you solve this death look issue of sqllite wal? It seams not that sqllite want to fix this issue.

jwatzman commented 9 years ago

Why do you think this has to do with the WAL file? Did I miss something in the link you posted?
If it is because that file is disappearing, do you know what's deleting it? Is it something other than HHVM, some cleanup script gone awry or something?
Yeah sqlite really seems like the right tool here, +1 on anything else being way overkill.

GreenRover commented 9 years ago

In the strace above you can see a flock for the not existing wal file.

I would say another hhvm process deleted wall file on exit sqlite_close

But i am not shure where the problem realy is.

jwatzman commented 9 years ago

OK, took a slightly closer look at this. I think the WAL file is a red herring. Here's part of the "new process" strace you gave:

open("/var/www/.hhvm.hhbc", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 6
fstat(6, {st_mode=S_IFREG|0644, st_size=29316096, ...}) = 0
lseek(6, 0, SEEK_SET)                   = 0
read(6, "SQLite format 3\0\4\0\1\1\0@  \0\2)x\0\0o\325"..., 100) = 100
fcntl(6, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)

That's all on fd 6 -- the file was opened, but we failed to lock it. Probably because another process already has the lock. The same is in your other strace -- trying to lock fd 13, and there isn't enough info in the strace to see what that fd actually is. (But all the opens on the wal/journal files fail, so it isn't trying to flock one of them, since we don't have an fd for it!)

So my suspicion is that you eventually get a ton of contention for the flock on the file because you have so many long-running HHVM processes running. Why do you have so many separate processes? Can you instead have a single process that you make web requests to, the standard server model, so only one has the DB open at a time? HHVM manages this fairly well, but wasn't really designed to have so many separate processes running at once. (You're doing a lot of duplicate work in each!)

If you really can't do that, it's possible to specify a different repo location per process. The INI setting is hhvm.repo.central.path or hhvm.repo.local.path, I don't recall the difference or which one you are supposed to set.

GreenRover commented 9 years ago

Hi, i dont have this much processes. 5-6 crons and a big one with pcntl_fork where the mother has the uw and the first client the ur status.

All other in the lsof list are cron jobs on hold since hours. because off the one uw.

jwatzman commented 9 years ago

Can you attach to the process holding the lock with gdb and run a backtrace, to figure out what it's doing in the nanosleep loop?

GreenRover commented 9 years ago

Hope that will help:

...
hhvm      28664      www-data    6ur     REG              252,0 14202880     264029 /var/www/.hhvm.hhbc
hhvm      28664      www-data   10ur     REG              252,0 14202880     264029 /var/www/.hhvm.hhbc
hhvm      28664      www-data   13ur     REG              252,0 14202880     264029 /var/www/.hhvm.hhbc
hhvm      28823      www-data    6u      REG              252,0 14202880     264029 /var/www/.hhvm.hhbc
hhvm      28823      www-data    9u      REG              252,0 14202880     264029 /var/www/.hhvm.hhbc
hhvm      28824      www-data    6uw     REG              252,0 14202880     264029 /var/www/.hhvm.hhbc
hhvm      28824      www-data    9uw     REG              252,0 14202880     264029 /var/www/.hhvm.hhbc
hhvm      28824      www-data   10uw     REG              252,0 14202880     264029 /var/www/.hhvm.hhbc
hhvm      28824      www-data   12u      REG              252,0     1544     268763 /var/www/.hhvm.hhbc-journal
....

gdb of 28824 http://pastebin.com/P5S4NJV5

gdb of 28664 http://pastebin.com/JvK7XjVs

gdb of 28823 http://pastebin.com/GWRqcmCE

For meantime i will go back to hhvm 3.0. The last stable release for me.

jwatzman commented 9 years ago

http://pastebin.com/JvK7XjVs is really interesting -- it looks like we were doing a sqlite operation, took a signal, ended up in bt_handler, which then tried to do another sqlite operation. My suspicion is that the latter hung waiting for the operation before it took the signal to complete, which of course it never can.

The signal handler only gets called on a few "bad" exceptions, so it seems likely that some other crash is the root cause.

jwatzman commented 9 years ago

That's probably enough info to fix the proximate issue (re-entering sqlite in a signal handler). Not sure what other info we could get to find the root cause (why we hit our "bad" signal handler in the middle of a sqlite operation).

GreenRover commented 9 years ago

But in HHVM 3.0 and before i dont have this problem. So a change made since 3.0 must be the cause the problem.

ehcpdeveloper commented 9 years ago

Similar issue, about hhvm futex contention: https://github.com/facebook/hhvm/issues/5081

GreenRover commented 3 years ago

Very out dated

facebook / hhvm

Death flock on .hhvm.hhbc #4676