[erlang-bugs] Fwd: VM locks up on write to socket (and now it seems to file too)

Erik Søe Sørensen <>
Mon Nov 26 13:22:16 CET 2012


Suggestions for things to look at:
- See what data size is sent, as seen from the Erlang side. Is the 2GB 
number correct?
- Verify endian-ness of the timestamps and data lengths you read from 
the file. "native"-endian may be correct, but is a bit of a funny thing 
to have in your file format. A mistake here may well cause your program 
to write more data than you intended.

As for how writev handles large values, my quick test on 64-bit Ubuntu 
shows that (on a non-socket file descriptor) it returns 
2147479552=0x7FFFF000 for an input size of 2158022464 -  i.e, it does 
return something reasonable and positive, but writes less than 2GB.
That doesn't necessarily say anything about how the behaviour is on a 
closed socket on CentOS, of course.

/Erik

On 26-11-2012 12:35, Peter Membrey wrote:
> Hi all,
>
> Trying to send again under a new account...
>
> Cheers,
>
> Pete
>
> ---------- Forwarded message ----------
> From: *Peter Membrey* < <mailto:>>
> Date: 24 November 2012 21:57
> Subject: Re: [erlang-bugs] VM locks up on write to socket (and now it 
> seems to file too)
> To: Patrik Nyblom < <mailto:>>
> Cc:  <mailto:>
>
>
> Hi guys,
>
> Thanks for getting back in touch so quickly!
>
> I did do an lsof on the process and I can confirm that it was
> definitely a socket. However by that time the application it had been
> trying to send to had been killed. When I checked the sockets were
> showing as waiting to close. Unfortunately I didn't think to do an
> lsof until after the apps had been shut down. I was hoping the VM
> would recover if I killed the app that had upset it. However even
> after all the apps connected had been shut down, the issue didn't
> resolve.
>
> The application receives requests from a client, which contains two
> data items. The stream ID and a timestamp. Both are encoded as big
> integer unsigned numbers. The server then looks through the file
> referenced by the stream ID and uses the timestamp as an index. The
> file format is currently really simple, in the form of:
>
> <Timestamp:64/native-integer,Length:32/native-integer,Data:Length/binary>>
>
> There is an index file that provides an offset into the file based on
> time stamp, but basically it opens the file, and reads sequentially
> through it until it finds the timestamps that it cares about. In this
> case it reads all data with a greater timestamp until the end of the
> file is reached. It's possible the client is sending an incorrect
> timestamp, and maybe too much data is being read. However the loop is
> very primitive - it reads all the data in one go before passing it
> back to the protocol handler to send down the socket; so by that time
> even though the response is technically incorrect and the app has
> failed, it should still not cause the VM any issues.
>
> The data is polled every 10 seconds by the client app so I would not
> expect there to be 2GB of new data to send. I'm afraid my C skills are
> somewhat limited, so I'm not sure how to put together a sample app to
> try out writev. The platform is 64bit CentOS 6.3 (equivalent to RHEL
> 6.3) so I'm not expecting any strange or weird behaviour from the OS
> level but of course I could be completely wrong there. The OS is
> running directly on hardware, so there's no VM layer to worry about.
>
> Hope this might offer some additional clues…
>
> Thanks again!
>
> Kind Regards,
>
> Peter Membrey
>
>
>
> On 24 November 2012 00:13, Patrik Nyblom < 
> <mailto:>> wrote:
> > Hi again!
> >
> > Could you go back to the version without the printouts and get back 
> to the
> > situation where writev loops returning 0 (as in the strace)? If so, 
> it would
> > be really interesting to see an 'lsof' of the beam process, to see 
> if this
> > file descriptor really is open and is a socket...
> >
> > The thing is that writev with a vector that is not empty, would 
> never return
> > 0 for a non blocking socket. Not on any modern (i.e. not ancient) POSIX
> > compliant system anyway. Of course it is a *really* large item you are
> > trying to write there, but it should be no problem for a 64bit linux.
> >
> > Also I think there is no use finding the Erlang code, I'll take that 
> back,
> > It would be more interesting to see what really happens at the OS/VM 
> level
> > in this case.
> >
> > Cheers,
> > Patrik
> >
> >
> > On 11/23/2012 01:49 AM, Loïc Hoguin wrote:
> >>
> >> Sending this on behalf of someone who didn't manage to get the 
> email sent
> >> to this list after 2 attempts. If someone can check if he's hold up or
> >> something that'd be great.
> >>
> >> Anyway he has a big issue so I hope I can relay the conversation 
> reliably.
> >>
> >> Thanks!
> >>
> >> On 11/23/2012 01:45 AM, Peter Membrey wrote:
> >>>
> >>> From: Peter Membrey < <mailto:>>
> >>> Date: 22 November 2012 19:02
> >>> Subject: VM locks up on write to socket (and now it seems to file too)
> >>> To:  <mailto:>
> >>>
> >>>
> >>> Hi guys,
> >>>
> >>> I wrote a simple database application called CakeDB
> >>> (https://github.com/pmembrey/cakedb) that basically spends its time
> >>> reading and writing files and sockets. There's very little in the way
> >>> of complex logic. It is running on CentOS 6.3 with all the updates
> >>> applied. I hit this problem on R15B02 so I rolled back to R15B01 but
> >>> the issue remained. Erlang was built from source.
> >>>
> >>> The machine has two Intel X5690 CPUs giving 12 cores plus HT. I've
> >>> tried various arguments for the VM but so far nothing has prevented
> >>> the problem. At the moment I'm using:
> >>>
> >>> +K
> >>> +A 6
> >>> +sbt tnnps
> >>>
> >>> The issue I'm seeing is that one of the scheduler threads will hit
> >>> 100% cpu usage and the entire VM will become unresponsive. When this
> >>> happens, I am not able to connect via the console with attach and
> >>> entop is also unable to connect. I can still establish TCP connections
> >>> to the application, but I never receive a response. A standard kill
> >>> signal will cause the VM to shut down (it doesn't need -9).
> >>>
> >>> Due to the pedigree of the VM I am quite willing to accept that I've
> >>> made a fundamental mistake in my code. I am pretty sure that the way I
> >>> am doing the file IO could result in some race conditions. However, my
> >>> poor code aside, from what I understand, I still shouldn't be able to
> >>> crash / deadlock the VM like this.
> >>>
> >>> The issue doesn't seem to be caused by load. The app can fail when
> >>> it's very busy, but also when it is practically idle. I haven't been
> >>> able to find a trigger or any other explanation for the failure.
> >>>
> >>> The thread maxing out the CPU is attempting to write data to the 
> socket:
> >>>
> >>> (gdb) bt
> >>> #0  0x00007f9882ab6377 in writev () from /lib64/libc.so.6
> >>> #1  0x000000000058a81f in tcp_inet_output (data=0x2407570,
> >>> event=<value optimized out>) at drivers/common/inet_drv.c:9681
> >>> #2  tcp_inet_drv_output (data=0x2407570, event=<value optimized out>)
> >>> at drivers/common/inet_drv.c:9601
> >>> #3  0x00000000004b773f in erts_port_task_execute (runq=0x7f98826019c0,
> >>> curr_port_pp=0x7f9881639338)  at beam/erl_port_task.c:858
> >>> #4  0x00000000004afd83 in schedule (p=<value optimized out>,
> >>> calls=<value optimized out>) at beam/erl_process.c:6533
> >>> #5  0x0000000000539ca2 in process_main () at beam/beam_emu.c:1268
> >>> #6  0x00000000004b1279 in sched_thread_func (vesdp=0x7f9881639280) at
> >>> beam/erl_process.c:4834
> >>> #7  0x00000000005ba726 in thr_wrapper (vtwd=0x7fff6cfe2300) at
> >>> pthread/ethread.c:106
> >>> #8  0x00007f9882f78851 in start_thread () from /lib64/libpthread.so.0
> >>> #9  0x00007f9882abe11d in clone () from /lib64/libc.so.6
> >>> (gdb)
> >>>
> >>> I then tried running strace on that thread and got (indefinitely):
> >>>
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> writev(15, [{"", 2158022464}], 1)       = 0
> >>> ...
> >>>
> >>>  From what I can tell, it's trying to write data to a socket, which is
> >>> succeeding, but writing 0 bytes. From the earlier definitions in the
> >>> source file, an error condition would be signified by a negative
> >>> number. Any other result is the number of bytes written, in this case
> >>> 0. I'm not sure if this is desired behaviour or not. I've tried
> >>> killing the application on the other end of the socket, but it has no
> >>> effect on the VM.
> >>>
> >>> I have enabled debugging for the inet code, so hopefully this will
> >>> give a little more insight. I am currently trying to reproduce the
> >>> condition, but as I really have no idea what causes it, it's pretty
> >>> much a case of wait and see.
> >>>
> >>>
> >>> **** UPDATE ****
> >>>
> >>> I managed to lock up the VM again, but this time it was caused by file
> >>> IO,
> >>> probably from the debugging statements. Although it worked fine 
> for some
> >>> time
> >>> the last entry in the file was cut off.
> >>>
> >>>  From GDB:
> >>>
> >>> (gdb) info threads
> >>>    53 Thread 0x7f83e988b700 (LWP 8621)  0x00007f83ea6da54d in read ()
> >>> from /lib64/libpthread.so.0
> >>>    52 Thread 0x7f83e8c8f700 (LWP 8622)  0x00007f83ea6d743c in
> >>> pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
> >>>    51 Thread 0x7f83e818d700 (LWP 8623)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    50 Thread 0x7f83e816b700 (LWP 8624)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    49 Thread 0x7f83e8149700 (LWP 8625)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    48 Thread 0x7f83e8127700 (LWP 8626)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    47 Thread 0x7f83e8105700 (LWP 8627)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    46 Thread 0x7f83e80e3700 (LWP 8628)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    45 Thread 0x7f83e80c1700 (LWP 8629)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    44 Thread 0x7f83e809f700 (LWP 8630)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    43 Thread 0x7f83e807d700 (LWP 8631)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    42 Thread 0x7f83e805b700 (LWP 8632)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    41 Thread 0x7f83e8039700 (LWP 8633)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    40 Thread 0x7f83e8017700 (LWP 8634)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    39 Thread 0x7f83e7ff5700 (LWP 8635)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    38 Thread 0x7f83e7fd3700 (LWP 8636)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    37 Thread 0x7f83e7fb1700 (LWP 8637)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    36 Thread 0x7f83e7f8f700 (LWP 8638)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    35 Thread 0x7f83e7f6d700 (LWP 8639)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    34 Thread 0x7f83e7f4b700 (LWP 8640)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    33 Thread 0x7f83e7f29700 (LWP 8641)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    32 Thread 0x7f83e7f07700 (LWP 8642)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    31 Thread 0x7f83e7ee5700 (LWP 8643)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    30 Thread 0x7f83e7ec3700 (LWP 8644)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    29 Thread 0x7f83e7ea1700 (LWP 8645)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    28 Thread 0x7f83e7e7f700 (LWP 8646)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    27 Thread 0x7f83d7c5a700 (LWP 8647)  0x00007f83ea6db09d in waitpid
> >>> () from /lib64/libpthread.so.0
> >>>    26 Thread 0x7f83d7c53700 (LWP 8648)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    25 Thread 0x7f83d7252700 (LWP 8649)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    24 Thread 0x7f83d6851700 (LWP 8650)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    23 Thread 0x7f83d5e50700 (LWP 8651)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    22 Thread 0x7f83d544f700 (LWP 8652)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    21 Thread 0x7f83d4a4e700 (LWP 8653)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    20 Thread 0x7f83d404d700 (LWP 8654)  0x00007f83ea20be7d in write ()
> >>> from /lib64/libc.so.6
> >>>    19 Thread 0x7f83d364c700 (LWP 8655)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    18 Thread 0x7f83d2c4b700 (LWP 8656)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    17 Thread 0x7f83d224a700 (LWP 8657)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    16 Thread 0x7f83d1849700 (LWP 8658)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    15 Thread 0x7f83d0e48700 (LWP 8659)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    14 Thread 0x7f83d0447700 (LWP 8660)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    13 Thread 0x7f83cfa46700 (LWP 8661)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    12 Thread 0x7f83cf045700 (LWP 8662)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    11 Thread 0x7f83ce644700 (LWP 8663)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    10 Thread 0x7f83cdc43700 (LWP 8664)  0x00007f83ea215ae9 in syscall
> >>> () from /lib64/libc.so.6
> >>>    9 Thread 0x7f83cd242700 (LWP 8665)  0x00007f83ea215ae9 in 
> syscall ()
> >>> from /lib64/libc.so.6
> >>>    8 Thread 0x7f83cc841700 (LWP 8666)  0x00007f83ea215ae9 in 
> syscall ()
> >>> from /lib64/libc.so.6
> >>>    7 Thread 0x7f83cbe40700 (LWP 8667)  0x00007f83ea215ae9 in 
> syscall ()
> >>> from /lib64/libc.so.6
> >>>    6 Thread 0x7f83cb43f700 (LWP 8668)  0x00007f83ea215ae9 in 
> syscall ()
> >>> from /lib64/libc.so.6
> >>>    5 Thread 0x7f83caa3e700 (LWP 8669)  0x00007f83ea215ae9 in 
> syscall ()
> >>> from /lib64/libc.so.6
> >>>    4 Thread 0x7f83ca03d700 (LWP 8670)  0x00007f83ea215ae9 in 
> syscall ()
> >>> from /lib64/libc.so.6
> >>>    3 Thread 0x7f83c963c700 (LWP 8671)  0x00007f83ea215ae9 in 
> syscall ()
> >>> from /lib64/libc.so.6
> >>>    2 Thread 0x7f83c8c3b700 (LWP 8672)  0x00007f83ea215ae9 in 
> syscall ()
> >>> from /lib64/libc.so.6
> >>> * 1 Thread 0x7f83eb3a8700 (LWP 8597)  0x00007f83ea211d03 in select ()
> >>> from /lib64/libc.so.6
> >>> (gdb)
> >>>
> >>>
> >>> (gdb) bt
> >>> #0  0x00007f83ea20be7d in write () from /lib64/libc.so.6
> >>> #1  0x00007f83ea1a2583 in _IO_new_file_write () from /lib64/libc.so.6
> >>> #2  0x00007f83ea1a3b35 in _IO_new_do_write () from /lib64/libc.so.6
> >>> #3  0x00007f83ea1a21fd in _IO_new_file_xsputn () from /lib64/libc.so.6
> >>> #4  0x00007f83ea17589d in vfprintf () from /lib64/libc.so.6
> >>> #5  0x00007f83ea18003a in printf () from /lib64/libc.so.6
> >>> #6  0x000000000058f0e8 in tcp_recv (desc=0x2c3d350, request_len=0) at
> >>> drivers/common/inet_drv.c:8976
> >>> #7  0x000000000058f63a in tcp_inet_input (data=0x2c3d350, event=<value
> >>> optimized out>) at drivers/common/inet_drv.c:9326
> >>> #8  tcp_inet_drv_input (data=0x2c3d350, event=<value optimized out>)
> >>> at drivers/common/inet_drv.c:9604
> >>> #9  0x00000000004b770f in erts_port_task_execute (runq=0x7f83e9d5d3c0,
> >>> curr_port_pp=0x7f83e8dc6e78) at beam/erl_port_task.c:851
> >>> #10 0x00000000004afd83 in schedule (p=<value optimized out>,
> >>> calls=<value optimized out>) at beam/erl_process.c:6533
> >>> #11 0x0000000000539ca2 in process_main () at beam/beam_emu.c:1268
> >>> #12 0x00000000004b1279 in sched_thread_func (vesdp=0x7f83e8dc6dc0) at
> >>> beam/erl_process.c:4834
> >>> #13 0x00000000005bb3e6 in thr_wrapper (vtwd=0x7fffe8266da0) at
> >>> pthread/ethread.c:106
> >>> #14 0x00007f83ea6d3851 in start_thread () from /lib64/libpthread.so.0
> >>> #15 0x00007f83ea21911d in clone () from /lib64/libc.so.6
> >>> (gdb)
> >>>
> >>> (gdb) bt
> >>> #0  0x00007f83ea6da54d in read () from /lib64/libpthread.so.0
> >>> #1  0x0000000000554b6e in signal_dispatcher_thread_func (unused=<value
> >>> optimized out>) at sys/unix/sys.c:2776
> >>> #2  0x00000000005bb3e6 in thr_wrapper (vtwd=0x7fffe8266c80) at
> >>> pthread/ethread.c:106
> >>> #3  0x00007f83ea6d3851 in start_thread () from /lib64/libpthread.so.0
> >>> #4  0x00007f83ea21911d in clone () from /lib64/libc.so.6
> >>> (gdb)
> >>>
> >>> (gdb) bt
> >>> #0  0x00007f83ea215ae9 in syscall () from /lib64/libc.so.6
> >>> #1  0x00000000005bba35 in wait__ (e=0x2989390) at
> >>> pthread/ethr_event.c:92
> >>> #2  ethr_event_wait (e=0x2989390) at pthread/ethr_event.c:218
> >>> #3  0x00000000004ae5bd in erts_tse_wait (fcalls=<value optimized out>,
> >>> esdp=0x7f83e8e2c440, rq=0x7f83e9d5e7c0) at beam/erl_threads.h:2319
> >>> #4  scheduler_wait (fcalls=<value optimized out>, esdp=0x7f83e8e2c440,
> >>> rq=0x7f83e9d5e7c0) at beam/erl_process.c:2087
> >>> #5  0x00000000004afb94 in schedule (p=<value optimized out>,
> >>> calls=<value optimized out>) at beam/erl_process.c:6467
> >>> #6  0x0000000000539ca2 in process_main () at beam/beam_emu.c:1268
> >>> #7  0x00000000004b1279 in sched_thread_func (vesdp=0x7f83e8e2c440) at
> >>> beam/erl_process.c:4834
> >>> #8  0x00000000005bb3e6 in thr_wrapper (vtwd=0x7fffe8266da0) at
> >>> pthread/ethread.c:106
> >>> #9  0x00007f83ea6d3851 in start_thread () from /lib64/libpthread.so.0
> >>> #10 0x00007f83ea21911d in clone () from /lib64/libc.so.6
> >>> (gdb)
> >>>
> >>>
> >>> (gdb) bt
> >>> #0  0x00007f83ea6db09d in waitpid () from /lib64/libpthread.so.0
> >>> #1  0x0000000000555a9f in child_waiter (unused=<value optimized out>)
> >>> at sys/unix/sys.c:2700
> >>> #2  0x00000000005bb3e6 in thr_wrapper (vtwd=0x7fffe8266d50) at
> >>> pthread/ethread.c:106
> >>> #3  0x00007f83ea6d3851 in start_thread () from /lib64/libpthread.so.0
> >>> #4  0x00007f83ea21911d in clone () from /lib64/libc.so.6
> >>> (gdb)
> >>>
> >>>
> >>> **** END UPDATE ****
> >>>
> >>>
> >>> I'm happy to provide any information I can, so please don't 
> hesitate to
> >>> ask.
> >>>
> >>> Thanks in advance!
> >>>
> >>> Kind Regards,
> >>>
> >>> Peter Membrey
> >>>
> >>
> >>
> >
> > _______________________________________________
> > erlang-bugs mailing list
> >  <mailto:>
> > http://erlang.org/mailman/listinfo/erlang-bugs
>


-- 
Mobile: + 45 26 36 17 55 | Skype: eriksoesorensen | Twitter: @eriksoe
Trifork A/S  |  Margrethepladsen 4  |  DK-8000 Aarhus C | 
www.trifork.com <http://www.trifork.com/>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-bugs/attachments/20121126/72c05553/attachment-0001.html>


More information about the erlang-bugs mailing list