Cassandra with CLI crash with cassandra stress

[slivne]

'''
I (Dor) run HEAD with c*,cli during cassandra-insert test got this

INFO 11:29:41 Initializing Keyspace1.Counter3
INFO 11:30:00 Enqueuing flush of Standard1: 163226520 (33%) on-heap, 0 (0%) off-heap
INFO 11:30:00 Writing Memtable-Standard1@1599189510(46948000 serialized bytes, 1067000 ops, 33%/0% of on/off-heap limit)
INFO 11:30:06 Completed flushing /usr/cassandra/data/data/Keyspace1/Standard1-600171f05d0311e4ab6821825188ddb3/Keyspace1-Standard1-ka-1-Data.db (59325200 bytes) for commitlog position ReplayPosition(segmentId=1414322891025, position=666049)
INFO 11:30:17 Enqueuing flush of Standard1: 163231110 (33%) on-heap, 0 (0%) off-heap
INFO 11:30:17 Writing Memtable-Standard1@642928385(46951300 serialized bytes, 1067075 ops, 33%/0% of on/off-heap limit)
page fault outside application, addr: 0x0000200000300000
[registers]
RIP: 0x0000000000465b61 <???+4610913>
RFL: 0x0000000000010202 CS: 0x0000000000000008 SS: 0x0000000000000010
RAX: 0x8000000000000000 RBX: 0x0000200000300004 RCX: 0x0000000000000000 RDX: 0x0000000000000000
RSI: 0x0000000000000000 RDI: 0x00002000002fbacc RBP: 0x00002000002fd7c0 R8: 0x0000000000000066
R9: 0x0000000000000000 R10: 0x00000000ffffffe4 R11: 0x0000000000000000 R12: 0x00000000ffffffff
R13: 0x0000000000000000 R14: 0x00000000ffffffe4 R15: 0x0000000000000000 RSP: 0x00002000002fba50
Aborted

[backtrace]
0x000000000032bc1f <???+3324959>
0x000000000032ce86 <mmu::vm_fault(unsigned long, exception_frame*)+358>
0x000000000038eeb9 <page_fault+105>
0x000000000038dda6 <???+3726758>
'''

[slivne]

We do not have an image with Cassandr and CLI

• Need to verify the issue is reproducible with current head
• Need to verify the issue does not happen with an image created with cassandra,httpserver
  • If the issue does not happen with this image we will push the fix milestone

[syuu1228]

I couldn't reproduce this at first when I tried cassandra-stress with image=cassandra,cli:

make image=cassandra,cli
./scripts/run.py -n -m 4G

# Another window
sh tools/bin/cassandra-stress -d 192.168.122.89 -o INSERT && sh tools/bin/cassandra-stress -t1000 -d 192.168.122.89 -o READ

But while I testing on #502, I realized that I could reproduce this with cassandra-stress + looping curl http://192.168.122.89:8000/os/threads with image=cassandra,httpserver:

make image=cassandra,httpserver
sudo scripts/run.py -c1 -nvV -m4G

# Another window
sh tools/bin/cassandra-stress -d 192.168.122.89 -o INSERT && sh tools/bin/cassandra-stress -t1000 -d 192.168.122.89 -o READ
# More window
 while :; do curl http://192.168.122.89:8000/os/threads;done

It not always immediately happen, sometimes it takes over several minutes to abort.

I'm not 100% sure, but it looks like does not occur on different APIs like /os/dmesg.

And even I could reproduce it with image=cli, it's more rare case, I able to see the fault only once:

[syuu@localhost osv]$ ./scripts/run.py -n
OSv v0.14-18-g41220e1
eth0: 192.168.122.89
/# page fault outside application, addr: 0x0000200000300000
[registers]
RIP: 0x000000000047336f <???+4666223>
RFL: 0x0000000000010202  CS:  0x0000000000000008  SS:  0x0000000000000010
RAX: 0x8000000000000000  RBX: 0x0000000000000000  RCX: 0x0000000000000001  RDX: 0x00002000002fdf1c
RSI: 0x0000000000000000  RDI: 0x00002000002fc35c  RBP: 0x00002000002fe050  R8:  0x00000000ffffffe4
R9:  0x0000200000300004  R10: 0x00000000ffffffff  R11: 0x0000000000000000  R12: 0x0000100000ce3296
R13: 0x0000200000300004  R14: 0x00000000ffffffff  R15: 0x0000000000000000  RSP: 0x00002000002fc2e0
Aborted

[backtrace]
0x000000000032d048 <???+3330120>
0x000000000032e27a <mmu::vm_fault(unsigned long, exception_frame*)+282>
0x0000000000390329 <page_fault+105>
0x000000000038f226 <???+3732006>

# Another window
./wrk -d 360 -t 8 -c 1000 http://192.168.122.89:8000/os/threads

Since it happens without cassandra, I don't think it's related to Java or cassandra.
Maybe it's httpserver but I don't have much evidence for now.

[syuu1228]

Few more information about the fault:
When fault happens, bad addr is always '0x0000200000300000', rip is always same, and backtrace always doesn't include symbol name.

[raphaelsc]

On Thu, Nov 6, 2014 at 1:55 AM, Takuya ASADA notifications@github.com
wrote:

Few more information about the fault:
When fault happens, bad addr is always '0x0000200000300000', rip is always
same, and backtrace always doesn't include symbol name.

Try getting backtrace from gdb instead.

—
Reply to this email directly or view it on GitHub
#536 (comment)
.

Raphael S. Carvalho

[syuu1228]

On gdb result, fault is occurring at https://github.com/cloudius-systems/musl/blob/master/src/stdio/vfprintf.c#L297.
Normally z == big, but when fault is occurring z == 0x0000200000300000.
Maybe e2 >= 0.
All these variables are local, so I'm not yet sure why it it happens but it likely related to this else condition:
https://github.com/cloudius-systems/musl/blob/master/src/stdio/vfprintf.c#L294

Caller of vfprintf is httpserver, because fmt_fp didn't called unless started to access REST URL.
Strangely, I cannot see caller of vfprintf. Return address was 0.

[syuu1228]

It was wrong, this only happens after fault > Strangely, I cannot see caller of vfprintf. Return address was 0.
This is when fault doesn't occurred:

#0  fmt_fp (f=f@entry=0x2000002fe380, y=1, w=0, p=p@entry=-1, fl=0, t=102)
    at /ssd/osv.3/musl/src/stdio/vfprintf.c:202
#1  0x0000000000468bc7 in printf_core (f=f@entry=0x2000002fe380, 
    fmt=fmt@entry=0x100000cb1755 "%f", ap=ap@entry=0x2000002fe208, 
    nl_arg=nl_arg@entry=0x2000002fe2a0, nl_type=nl_type@entry=0x2000002fe220)
    at /ssd/osv.3/musl/src/stdio/vfprintf.c:628
#2  0x00000000004692ea in vfprintf (f=f@entry=0x2000002fe380, 
    fmt=0x100000cb1755 "%f", ap=<optimized out>)
    at /ssd/osv.3/musl/src/stdio/vfprintf.c:673
#3  0x00000000004395b1 in vsnprintf (s=<optimized out>, n=<optimized out>, 
    fmt=<optimized out>, ap=<optimized out>)
    at /ssd/osv.3/libc/stdio/vsnprintf.c:33
#4  0x0000100000c63204 in ?? ()
#5  0x002f006100740061 in ?? ()
#6  0x0061007400610064 in ?? ()
#7  0x0064006e00610073 in ?? ()
#8  0x0064002f00610072 in ?? ()
#9  0x007200730075002f in ?? ()
#10 0x007300610063002f in ?? ()
#11 0x0000000000000001 in ?? ()
#12 0x00000072feb400ba in ?? ()
#13 0x0000000000000000 in ?? ()

But why we don't have these symbol names?

[raphaelsc]

On Thu, Nov 6, 2014 at 6:05 AM, Takuya ASADA notifications@github.com
wrote:

It was wrong, this only happens after fault > Strangely, I cannot see
caller of vfprintf. Return address was 0.
This is when fault doesn't occurred:

#0 fmt_fp (f=f@entry=0x2000002fe380, y=1, w=0, p=p@entry=-1, fl=0, t=102)
at /ssd/osv.3/musl/src/stdio/vfprintf.c:202
#1 0x0000000000468bc7 in printf_core (f=f@entry=0x2000002fe380,
fmt=fmt@entry=0x100000cb1755 "%f", ap=ap@entry=0x2000002fe208,
nl_arg=nl_arg@entry=0x2000002fe2a0, nl_type=nl_type@entry=0x2000002fe220)
at /ssd/osv.3/musl/src/stdio/vfprintf.c:628
#2 0x00000000004692ea in vfprintf (f=f@entry=0x2000002fe380,
fmt=0x100000cb1755 "%f", ap=)
at /ssd/osv.3/musl/src/stdio/vfprintf.c:673
#3 0x00000000004395b1 in vsnprintf (s=, n=,
fmt=, ap=)
at /ssd/osv.3/libc/stdio/vsnprintf.c:33
#4 0x0000100000c63204 in ?? ()
#5 0x002f006100740061 in ?? ()
#6 0x0061007400610064 in ?? ()
#7 0x0064006e00610073 in ?? ()
#8 0x0064002f00610072 in ?? ()
#9 0x007200730075002f in ?? ()
#10 0x007300610063002f in ?? ()
#11 0x0000000000000001 in ?? ()
#12 0x00000072feb400ba in ?? ()
#13 0x0000000000000000 in ?? ()

But why we don't have these symbol names?

Did you use 'osv syms' before 'bt'? If it doesn't work, try instead with
OSv in debug mode.

—
Reply to this email directly or view it on GitHub
#536 (comment)
.

Raphael S. Carvalho

[syuu1228]

This is not when fault, but breaking at fmt_fp, I could get symbol name on debug mode & osv syms.
And it was httpserver's os API.

#0  fmt_fp (f=f@entry=0x2000002fe380, y=1, w=0, p=p@entry=-1, fl=0, t=102)
    at /ssd/osv.7/musl/src/stdio/vfprintf.c:202
#1  0x0000000000469d47 in printf_core (f=f@entry=0x2000002fe380, 
    fmt=fmt@entry=0x100000cc28f1 "%f", ap=ap@entry=0x2000002fe208, 
    nl_arg=nl_arg@entry=0x2000002fe2a0, nl_type=nl_type@entry=0x2000002fe220)
    at /ssd/osv.7/musl/src/stdio/vfprintf.c:621
#2  0x000000000046a46a in vfprintf (f=f@entry=0x2000002fe380, 
    fmt=0x100000cc28f1 "%f", ap=<optimized out>)
    at /ssd/osv.7/musl/src/stdio/vfprintf.c:666
#3  0x000000000043a6d1 in vsnprintf (s=<optimized out>, n=<optimized out>, 
    fmt=<optimized out>, ap=<optimized out>)
    at /ssd/osv.7/libc/stdio/vsnprintf.c:33
#4  0x0000100000c67cd4 in __gnu_cxx::__to_xstring<std::string, char> (
    __convf=<optimized out>, __n=__n@entry=58, 
    __fmt=__fmt@entry=0x100000cc28f1 "%f")
    at /usr/include/c++/4.8.3/ext/string_conversions.h:95
#5  0x0000100000c89b83 in to_string (__val=<optimized out>)
    at /usr/include/c++/4.8.3/bits/basic_string.h:2903
#6  httpserver::json::formatter::to_json (f=<optimized out>)
    at json/formatter.cc:49
#7  0x0000100000c9fc5e in httpserver::json::json_element<float>::to_string (
    this=<optimized out>) at ./json/json_elements.hh:115
#8  0x0000100000c8c4ca in add (element=0x2000002fe8e8, this=0x2000002fe690)
---Type <return> to continue, or q <return> to quit---
    at json/json_elements.cc:57
#9  httpserver::json::json_base::to_json (this=<optimized out>)
    at json/json_elements.cc:93
#10 0x0000100000c89ada in httpserver::json::formatter::to_json (obj=...)
    at json/formatter.cc:67
#11 0x0000100000ca0cfc in httpserver::json::formatter::to_json<httpserver::json::Thread> (vec=...) at ./json/formatter.hh:90
#12 0x0000100000ca0dcd in httpserver::json::json_list<httpserver::json::Thread>::to_string (this=<optimized out>) at ./json/json_elements.hh:144
#13 0x0000100000c8c4ca in add (element=0x2000002fee80, this=0x2000002fec40)
    at json/json_elements.cc:57
#14 httpserver::json::json_base::to_json (this=<optimized out>)
    at json/json_elements.cc:93
#15 0x0000100000c89ada in httpserver::json::formatter::to_json (obj=...)
    at json/formatter.cc:67
#16 0x0000100000c9e38f in json_return_type<httpserver::json::Threads> (
    _res=..., this=0x2000002ff060) at ./json/json_elements.hh:220
#17 std::_Function_handler<httpserver::json::json_return_type(const http::server::request&), httpserver::api::os::init(httpserver::routes&)::__lambda16>::_M_invoke(const std::_Any_data &, const http::server::request &) (__functor=..., 
    __args#0=...) at /usr/include/c++/4.8.3/functional:2057
#18 0x0000100000c80b51 in operator() (__args#0=..., this=<optimized out>)
    at /usr/include/c++/4.8.3/functional:2471
---Type <return> to continue, or q <return> to quit---
#19 operator() (rep=..., req=..., __closure=<optimized out>) at handlers.hh:297
#20 std::_Function_handler<std::string (http::server::request const&, http::server::reply&), httpserver::function_handler::function_handler(std::function<httpserver::json::json_return_type (http::server::request const&)> const&)::{lambda(http::server::request const&, http::server::reply&)#1}>::_M_invoke(std::_Any_data const&, http::server::request const&, http::server::reply&) (__functor=..., 
    __args#0=..., __args#1=...) at /usr/include/c++/4.8.3/functional:2057
#21 0x0000100000c668aa in operator() (__args#1=..., __args#0=..., 
    this=0xffffa00003fc6da0) at /usr/include/c++/4.8.3/functional:2471
#22 httpserver::function_handler::handle (this=0xffffa00003fc6d80, path=..., 
    parts=<optimized out>, req=..., rep=...) at handlers.cc:140
#23 0x0000100000c638cc in httpserver::routes::handle (this=<optimized out>, 
    path="/os/threads", req=..., rep=...) at routes.cc:48
#24 0x0000100000c87fa0 in http::server::request_handler::handle_request (
    this=0xffffa00003a9c6c8, req=..., rep=...) at request_handler.cc:113
#25 0x0000100000c85c62 in operator() (__closure=<optimized out>, 
    bytes_transferred=<optimized out>, ec=...) at connection.cc:278
#26 std::_Function_handler<void(boost::system::error_code, long unsigned int), http::server::connection::do_read()::__lambda3>::_M_invoke(const std::_Any_data &, boost::system::error_code, unsigned long) (__functor=..., __args#0=..., 
    __args#1=55) at /usr/include/c++/4.8.3/functional:2071
#27 0x0000100000c831c5 in operator() (__args#1=<optimized out>, __args#0=..., 
    this=0x2000002ff490) at /usr/include/c++/4.8.3/functional:2471
---Type <return> to continue, or q <return> to quit---
#28 operator() (this=0x2000002ff490)
    at /ssd/osv.7/external/x64/misc.bin/usr/include/boost/asio/detail/bind_handler.hpp:127
#29 asio_handler_invoke<boost::asio::detail::binder2<std::function<void(boost::system::error_code, long unsigned int)>, boost::system::error_code, long unsigned int> > (function=...)
    at /ssd/osv.7/external/x64/misc.bin/usr/include/boost/asio/handler_invoke_hook.hpp:64
#30 invoke<boost::asio::detail::binder2<std::function<void(boost::system::error_code, long unsigned int)>, boost::system::error_code, long unsigned int>, std::function<void(boost::system::error_code, long unsigned int)> > (context=..., 
    function=...)
    at /ssd/osv.7/external/x64/misc.bin/usr/include/boost/asio/detail/handler_invoke_helpers.hpp:37
#31 boost::asio::detail::reactive_socket_recv_op<boost::asio::mutable_buffers_1, std::function<void (boost::system::error_code, unsigned long)> >::do_complete(boost::asio::detail::task_io_service*, boost::asio::detail::task_io_service_operation*, boost::system::error_code const&, unsigned long) (
    owner=<optimized out>, base=0xffffa00100baad00)
    at /ssd/osv.7/external/x64/misc.bin/usr/include/boost/asio/detail/reactive_socket_recv_op.hpp:110
#32 0x0000100000c7bb7f in complete (bytes_transferred=<optimized out>, ec=..., 
    owner=..., this=0xffffa00100baad00)
---Type <return> to continue, or q <return> to quit---
    at /ssd/osv.7/external/x64/misc.bin/usr/include/boost/asio/detail/task_io_service_operation.hpp:37
#33 do_run_one (ec=..., this_thread=..., lock=..., this=0xffffa000032c3f00)
    at /ssd/osv.7/external/x64/misc.bin/usr/include/boost/asio/detail/impl/task_io_service.ipp:384
#34 boost::asio::detail::task_io_service::run (this=0xffffa000032c3f00, ec=...)
    at /ssd/osv.7/external/x64/misc.bin/usr/include/boost/asio/detail/impl/task_io_service.ipp:153
#35 0x0000100000c78b96 in run (this=0xffffa00003a9c680)
    at /ssd/osv.7/external/x64/misc.bin/usr/include/boost/asio/impl/io_service.ipp:59
#36 http::server::server::run (this=0xffffa00003a9c680) at server.cc:100
#37 0x0000100000c7f117 in httpserver::global_server::run (_config=...)
    at global_server.cc:91
#38 0x0000100000c5342e in main (argc=<optimized out>, argv=<optimized out>)
    at main.cc:48
#39 0x00000000004101ab in osv::application::run_main (
    this=this@entry=0xffffa00003172618, path="/libhttpserver.so", 
    argc=argc@entry=1, argv=argv@entry=0xffffa00002a0d780)
    at /ssd/osv.7/core/app.cc:240
#40 0x0000000000411958 in osv::application::run_main (
    this=this@entry=0xffffa00003172618) at /ssd/osv.7/core/app.cc:257
#41 0x000000000020c0c9 in osv::application::main (this=0xffffa00003172618)
---Type <return> to continue, or q <return> to quit---
    at /ssd/osv.7/core/app.cc:197
#42 0x0000000000411c29 in operator() (__closure=0x0, app=<optimized out>)
    at /ssd/osv.7/core/app.cc:155
#43 osv::application::__lambda3::_FUN (app=<optimized out>)
    at /ssd/osv.7/core/app.cc:157
#44 0x000000000043f976 in operator() (__closure=0xffffa000031dae00)
    at /ssd/osv.7/libc/pthread.cc:98
#45 std::_Function_handler<void(), pthread_private::pthread::pthread(void* (*)(void*), void*, sigset_t, const pthread_private::thread_attr*)::__lambda6>::_M_invoke(const std::_Any_data &) (__functor=...)
    at /usr/include/c++/4.8.3/functional:2071
#46 0x00000000003eca38 in main (this=0xffff800003e3c050)
    at /ssd/osv.7/core/sched.cc:1000
#47 sched::thread_main_c (t=0xffff800003e3c050)
    at /ssd/osv.7/arch/x64/arch-switch.hh:144
#48 0x0000000000391286 in thread_main () at /ssd/osv.7/arch/x64/entry.S:113

[syuu1228]

On -O1, the bug disappear with -fno-move-loop-invariants.
On -O2, looks like we need some more '-fno-' flags, the bug disappear at least following flags:

-fno-aggressive-loop-optimizations -fno-align-jumps -fno-align-labels -fno-align-loops \
-fno-asynchronous-unwind-tables -fno-branch-count-reg -fno-inline -fno-inline-atomics \
-fno-inline-functions-called-once -fno-inline-small-functions -fno-ipa-cp -fno-ipa-profile \
-fno-ipa-pure-const -fno-ipa-reference -fno-ipa-sra -fno-ira-hoist-pressure -fno-ivopts \
-fno-jump-tables -fno-math-errno -fno-merge-constants -fno-move-loop-invariants

I'm testing to specify which one (or more) is triggering bug on -O2 now.

[penberg]

@syuu1228 The backtrace points to the thread listing RESTful API that IIRC was added by @nyh. It's probably printing out thread priority or something like that. Is it possible that we're printing out information for a thread that's being destroyed?

[nyh]

On Mon, Nov 10, 2014 at 4:46 PM, Pekka Enberg notifications@github.com
wrote:

@syuu1228 https://github.com/syuu1228 The backtrace points to the
thread listing RESTful API that IIRC was added by @nyh
https://github.com/nyh. It's probably printing out thread priority or
something like that. Is it possible that we're printing out information for
a thread that's being destroyed?

After yesterday's Makefile bug nothing would surprise me. But the way I
thought the HTTP server worked (but amnon, please correct me here), is
that my code (in httpserver/api/os.cc) first builds an object containing
floating-point numbers, etc., and only after that is all done, this object
is converted to a string. So if the conversion is what fails, it can't be
that it's because the thread was being destroyed.

Also, thread destruction should not have been a problem (at least, in
theory) because the os.cc code uses sched::with_all_threads(). This
function holds the "thread_map_mutex" lock, and thread's destructor
(thread::~thread) holds this mutex to remove itself from the list, so we
should have been safe against thread destruction (the "/os/threads" API
request delays thread destruction for its duration).

Nadav Har'El
nyh@cloudius-systems.com

[gleb-cloudius]

On Mon, Nov 10, 2014 at 08:29:11AM -0800, nyh wrote:

On Mon, Nov 10, 2014 at 4:46 PM, Pekka Enberg notifications@github.com
wrote:

@syuu1228 https://github.com/syuu1228 The backtrace points to the
thread listing RESTful API that IIRC was added by @nyh
https://github.com/nyh. It's probably printing out thread priority or
something like that. Is it possible that we're printing out information for
a thread that's being destroyed?

After yesterday's Makefile bug nothing would surprise me. But the way I
thought the HTTP server worked (but amnon, please correct me here), is
that my code (in httpserver/api/os.cc) first builds an object containing
floating-point numbers, etc., and only after that is all done, this object
is converted to a string. So if the conversion is what fails, it can't be
that it's because the thread was being destroyed.

We had exactly same failure before. It happened because of corrupted FPU
state and was fixed by 0e8d9b5. I am certain we have something
similar here.

        Gleb.