Crash on ORDER BY in OQGRAPH v3

[Arjen Lentz]

SELECT * FROM graph WHERE latch=1 AND origid=1 AND destid=6;
works

SELECT * FROM graph WHERE latch=1 AND origid=1 AND destid=6 ORDER BY seq;
segfaults.

[Andrew McDonnell (andymc73)]

Looks like clobbered memory

#0 0x00007fb46af1f45c in __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1 0x0000000000dbbd72 in my_write_core (sig=11) at /home/andrew/develop/maria/repo/oqgraph-varchar/mysys/stacktrace.c:457
#2 0x00000000007e00b2 in handle_fatal_signal (sig=11) at /home/andrew/develop/maria/repo/oqgraph-varchar/sql/signal_handler.cc:262
#3 <signal handler called>
#4 0x00007fb45d7b8c9d in oqgraph3::intrusive_ptr_release (ptr=0xa5a5a5a5a5a5a5a5) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.h:132
#5 0x00007fb45d7bb90f in boost::intrusive_ptr<oqgraph3::cursor>::~intrusive_ptr (this=0x7fb45d4aae90, __in_chrg=<optimized out>) at /usr/include/boost/smart_ptr/intrusive_ptr.hpp:101
#6 0x00007fb45d7bba34 in boost::intrusive_ptr<oqgraph3::cursor>::operator= (this=0x227d598, rhs=...) at /usr/include/boost/smart_ptr/intrusive_ptr.hpp:133
#7 0x00007fb45d7b8b8f in oqgraph3::cursor_ptr::operator= (this=0x227d598) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.h:58
#8 0x00007fb45d7bad13 in oqgraph3::edge_info::operator= (this=0x227d598) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.h:68
#9 0x00007fb45d7bb41f in open_query::reference::operator= (this=0x227d588) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/graphcore.cc:136
#10 0x00007fb45d7bb45d in open_query::stack_cursor::current (this=0x227a140, ref=...) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/graphcore.cc:274
#11 0x00007fb45d7b781c in open_query::oqgraph::row_ref (this=0x208f460, ref_ptr=0x227d588) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/graphcore.cc:948
#12 0x00007fb45d7b2d62 in ha_oqgraph::position (this=0x2277988, record=0x2278bf8 "\310\001\061") at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/ha_oqgraph.cc:1020
#13 0x00000000007dbe04 in find_all_keys (param=0x7fb45d4ab490, select=0x2282d20, fs_info=0x7fb45d4ab510, buffpek_pointers=0x7fb45d4ab150, tempfile=0x7fb45d4ab2f0, pq=0x0, found_rows=0x7fb45d4ab700) at /home/andrew/develop/maria/repo/oqgraph-varchar/sql/filesort.cc:650
#14 0x00000000007dad37 in filesort (thd=0x232e6a0, table=0x2276f90, sortorder=0x22837c8, s_length=1, select=0x2282d20, max_rows=18446744073709551615, sort_positions=false, examined_rows=0x7fb45d4ab708, found_rows=0x7fb45d4ab700) at /home/andrew/develop/maria/repo/oqgraph-varchar/sql/filesort.cc:294
#15 0x0000000000675c1c in create_sort_index (thd=0x232e6a0, join=0x23836f8, order=0x2383600, filesort_limit=18446744073709551615, select_limit=18446744073709551615, is_order_by=true) at /home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_select.cc:19220
#16 0x000000000064e157 in JOIN::exec_inner (this=0x23836f8) at /home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_select.cc:2929
#17 0x000000000064b6a7 in JOIN::exec (this=0x23836f8) at /home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_select.cc:2255
#18 0x000000000064ec3e in mysql_select (thd=0x232e6a0, rref_pointer_array=0x2331a60, tables=0x2382480, wild_num=1, fields=..., conds=0x2...

[Andrew McDonnell (andymc73)]

Seems to be because

ha_oqgraph::position() --> oqgraph::row_ref() --> cursor->current() --> ...

ends up at ref= last;

where struct open_query::reference assignment operator ends up at oqgraph3::cursor_ptr::operator= (which is implicit)
--> intrusive_ptr operator= which for some reason is designed to swap the input argument with itself.
Which means if your try and assign _to_ garbage memory, you end up with garbage in the thing being assigned from.
Hence crash.

Question is, why does intrusive_ptr use swap (i.e, its more than an 'usual' assignment operator) - the 'why' is not described in the doco. This ends up clobbering last which then crashes in intrusive_ptr_release.

Looking at graphcore.cc, AFAICS member last is actually only ever used in a local fashion... I can only assume done this way to save stack space or initalisation or something?

More important question: should ha_oqgraph::position(record) be being called with 'ref' set to point to junk (uninitialised?) memory?

[Andrew McDonnell (andymc73)]

perhaps cursor is invalid...?

no,

line 945... of graphcore.cc
  void oqgraph::row_ref(void *ref_ptr) throw()
  {
    reference &ref= *(reference*) ref_ptr; <-- ref ends up having junk (0xa5a5a5a5) in it
    if (cursor)
      cursor->current(ref);
    else
      ref= reference();
  }

So, looking at what I can find on mysql: position() gets called after each rnd_next()
So maybe our bug is in there...

So using the debugger, it appears rnd_next() is NOT called in this case?

[Andrew McDonnell (andymc73)]

For some reason rnd_init never gets called, And from the sql code, position first gets called before rnd_next

[Andrew McDonnell (andymc73)]

I think I fixed this, by calling row_ref from index_read() before the cursor gets set (and using in place new)

=== modified file 'storage/oqgraph/graphcore.cc'
--- storage/oqgraph/graphcore.cc 2013-08-09 11:20:16 +0000
+++ storage/oqgraph/graphcore.cc 2013-08-11 14:29:41 +0000
@@ -947,7 +947,7 @@
     if (cursor)
       cursor->current(ref);
     else
- ref= reference();
+ new (ref_ptr) reference(); // avoid assignment operator because the intrusive_ptr swaps for unknown reasons, which means if ref is uninitialised it segfaults
   }

=== modified file 'storage/oqgraph/ha_oqgraph.cc'
--- storage/oqgraph/ha_oqgraph.cc 2013-08-10 15:01:12 +0000
+++ storage/oqgraph/ha_oqgraph.cc 2013-08-11 14:31:05 +0000
@@ -740,6 +740,7 @@
    enum ha_rkey_function find_flag)
 {
   DBUG_ASSERT(inited==INDEX);
+ graph->row_ref((void*) ref); // reset before we have a cursor, so the memory is inited, avoiding the sefgault in position() when select with order by (bug #1133093)
   return index_read_idx(buf, active_index, key, key_len, find_flag);
 }

Problem is it now causes an assertion inside myisam via closefrm() when closing edges in ha_oqgraph::close() when DROP TABLE at finish of test

Looks like a cursor didn't close something somewhere? And I really don't understand how to fix this one :-(

[Andrew McDonnell (andymc73)]

Running without the drop at the end of the test indicates root cause is a memory leak

130812 19:23:46 [Note] /home/andrew/develop/maria/repo/oqgraph-varchar/build/sql/mysqld: ready for connections.
Version: '10.0.1-MariaDB-debug-log' socket: '/home/andrew/develop/maria/repo/oqgraph-varchar/build/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution
Warning: 984 bytes lost, allocated by T@2 at mysys/my_alloc.c:233, sql/thr_malloc.cc:77, sql/field.h:163, sql/field.cc:9501, sql/table.cc:1590, sql/table.cc:747, ??:0, sql/handler.cc:2347
Warning: 1744 bytes lost, allocated by T@2 at mysys/my_alloc.c:233, sql/sql_list.h:43, myisam/ha_myisam.cc:128, sql/handler.cc:252, sql/table.cc:1370, sql/table.cc:747, ??:0, sql/handler.cc:2347
Warning: 984 bytes lost, allocated by T@2 at mysys/my_alloc.c:233, ??:0, sql/handler.cc:2347, sql/table.cc:2663, sql/sql_base.cc:3207, sql/sql_base.cc:4564, sql/sql_base.cc:5115, sql/sql_base.cc:5718
Memory lost: 3712 bytes in 2204 chunks
mysqld: /home/andrew/develop/maria/repo/oqgraph-varchar/sql/sql_class.cc:1572: virtual THD::~THD(): Assertion `status_var.memory_used == 0' failed.

I did some funky stuff in gdb and worked out that the oqgraph3::cursor has a reference count that never falls to zero:

andrew@atlantis3:~/develop/maria$ egrep '_ref_count|#2' refs1.txt | paste - -|grep cursor
163 ptr->_ref_count++; #2 0x00000000009a5e9c in oqgraph3::cursor::cursor (this=0x22c3f10, graph=...) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:69
163 ptr->_ref_count++; #2 0x00000000009a5e9c in oqgraph3::cursor::cursor (this=0x22c4130, graph=...) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:69
163 ptr->_ref_count++; #2 0x00000000009a5e9c in oqgraph3::cursor::cursor (this=0x22d6de0, graph=...) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:69
163 ptr->_ref_count++; #2 0x00000000009a5e9c in oqgraph3::cursor::cursor (this=0x22d6eb0, graph=...) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:69
163 ptr->_ref_count++; #2 0x00000000009a5e9c in oqgraph3::cursor::cursor (this=0x22d7670, graph=...) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:69
163 ptr->_ref_count++; #2 0x00000000009a5e9c in oqgraph3::cursor::cursor (this=0x22d7740, graph=...) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:69
168 ptr->_ref_count--; #2 0x00000000009a659f in oqgraph3::cursor::~cursor (this=0x22d6eb0, __in_chrg=<optimized out>) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:93
168 ptr->_ref_count--; #2 0x00000000009a659f in oqgraph3::cursor::~cursor (this=0x22d6de0, __in_chrg=<optimized out>) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:93
163 ptr->_ref_count++; #2 0x00000000009a5e9c in oqgraph3::cursor::cursor (this=0x22d7020, graph=...) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.cc:69
163 ptr->_ref_count++; #...

[Andrew McDonnell (andymc73)]

OK - there was a memory leak in find_vertex which I fixed.

More problematic is another one:
 graphcore.cc:378
         if (record_weight && u != v)
          {
            typename graph_traits<Graph>::out_edge_iterator ei, ei_end;
            for (boost::tuples::tie(ei, ei_end)= out_edges(v, g); ei != ei_end; ++ei)
            {
              if (target(*ei, g) == u)
              {
                edge= *ei;
                weight= get(boost::edge_weight, g, *ei);
                break;
              }
            }
          }

out_edges causes two oqgraph3::cursor object to be constructed.
However tracking through with the debugger only ever shows one of them being destroyed.
For some reason the other underlying intrusive pointer never gets released.
This is the 'start' cursor created on line 295 of oqgraph_shim.h

I dont know why this is the case.
I mocked up a test of using boost_tie and a similar construct of classes and all the equivalent pointers eventually get freed so I dont think its a boost bug

[Andrew McDonnell (andymc73)]

Back to an assertion crash still happening at exit, a bit more detective work:

Assertion: inited on `edges` (backing store) not clearing to zero before close. SO memory breakpoint on my_isam inited.

Looks like for some reason the matching ha_index_end never gets called after seek_to initialises.

Downstream from graphcore.cc:768 case DIJKSTRAS | HAVE_ORIG | HAVE_DEST

Ultimately, it looks like
oqgraph_shim.h:292
    oqgraph3::cursor*
        end= new oqgraph3::cursor(const_cast<oqgraph3::graph*>(&g));
    oqgraph3::cursor*
        start= new oqgraph3::cursor(const_cast<oqgraph3::graph*>(&g));
    start->seek_to(v, boost::none); <-- never has a corresponding path which calls ha_index_end
    return std::make_pair(
        graph_traits<oqgraph3::graph>::out_edge_iterator(start),
        graph_traits<oqgraph3::graph>::out_edge_iterator(end));

[Andrew McDonnell (andymc73)]

Summary of status:

I think we can close this and open a new one against the debug build. Maybe.

The raw segfault was caused by something using a thing called an 'intrusive_ptr' which is used to add reference counting. However its copy cnstructor has odd sematics such that the assignment operator actually does a swap operation with the assignee(!), which means if the memory you are assigning to is uninitialised, you end up with junk in where you were copying from, which causes a crash when the assignee is destructed.

#3 <signal handler called>
#4 0x000000000098f292 in oqgraph3::intrusive_ptr_release (ptr=0xa5a5a5a5a5a5a5a5) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.h:132
#5 0x0000000000991e19 in boost::intrusive_ptr<oqgraph3::cursor>::~intrusive_ptr (this=0x7fe72e1f5ed0, __in_chrg=<optimized out>) at /usr/include/boost/smart_ptr/intrusive_ptr.hpp:101
#6 0x0000000000991f1a in boost::intrusive_ptr<oqgraph3::cursor>::operator= (this=0x22bef68, rhs=...) at /usr/include/boost/smart_ptr/intrusive_ptr.hpp:133
#7 0x000000000098f1a5 in oqgraph3::cursor_ptr::operator= (this=0x22bef68) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.h:58

The memory coming from the SQL core (the 'ref') via index_read is uninitalised when we first see it, but we seem to use it as a persistent storage area (I dont fully understand how all thatworks as yet, and ha_example.cc "explains" it but doesnt really...)

Thus, in-place should theoretically sort that one out:

     if (cursor)
       cursor->current(ref);
     else
- ref= reference();
+ new (ref_ptr) reference();

This actually passes the regression test now in a normal build!
In a debug build however, it is failing... tracing through with the debugger I worked out we can reset the contents of the ref via ha_oqgraph::index_read which seems to be called once at the start of the query:

 {
   DBUG_ASSERT(inited==INDEX);
+ graph->row_ref((void*) ref); // reset before we have a cursor, so the memory is inited, avoiding the sefgault in position() when select with order by (bug #1133093)
   return index_read_idx(buf, active_index, key, key_len, find_flag);
 }

THIS now fixes the segfault, but causes an assertion indicating we havent properly closed something in my_isam; specifically, the edges->file table, we have missed a closing ha_index_end(). This is where I finally got stuck...

The 'normal' build still passes...

[Antony T Curtis (atcurtis)]

How it was was probably correct - intrusive_ptr can be confusing - what you may need to look at is constructor initialisation or use in-place initialisation elsewhere otherwise, the explicit in-place you're doing will leave memory leak.

On 15 Aug, 2013, at 7:23 am, Andrew McDonnell wrote:

> Summary of status:
>
> I think we can close this and open a new one against the debug build.
> Maybe.
>
> The raw segfault was caused by something using a thing called an
> 'intrusive_ptr' which is used to add reference counting. However its
> copy cnstructor has odd sematics such that the assignment operator
> actually does a swap operation with the assignee(!), which means if the
> memory you are assigning to is uninitialised, you end up with junk in
> where you were copying from, which causes a crash when the assignee is
> destructed.
>
> #3 <signal handler called>
> #4 0x000000000098f292 in oqgraph3::intrusive_ptr_release (ptr=0xa5a5a5a5a5a5a5a5) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.h:132
> #5 0x0000000000991e19 in boost::intrusive_ptr<oqgraph3::cursor>::~intrusive_ptr (this=0x7fe72e1f5ed0, __in_chrg=<optimized out>) at /usr/include/boost/smart_ptr/intrusive_ptr.hpp:101
> #6 0x0000000000991f1a in boost::intrusive_ptr<oqgraph3::cursor>::operator= (this=0x22bef68, rhs=...) at /usr/include/boost/smart_ptr/intrusive_ptr.hpp:133
> #7 0x000000000098f1a5 in oqgraph3::cursor_ptr::operator= (this=0x22bef68) at /home/andrew/develop/maria/repo/oqgraph-varchar/storage/oqgraph/oqgraph_thunk.h:58
>
> The memory coming from the SQL core (the 'ref') via index_read is
> uninitalised when we first see it, but we seem to use it as a persistent
> storage area (I dont fully understand how all thatworks as yet, and
> ha_example.cc "explains" it but doesnt really...)
>
> Thus, in-place should theoretically sort that one out:
>
> if (cursor)
> cursor->current(ref);
> else
> - ref= reference();
> + new (ref_ptr) reference();
>
> This actually passes the regression test now in a normal build!
> In a debug build however, it is failing... tracing through with the debugger I worked out we can reset the contents of the ref via ha_oqgraph::index_read which seems to be called once at the start of the query:
>
> {
> DBUG_ASSERT(inited==INDEX);
> + graph->row_ref((void*) ref); // reset before we have a cursor, so the memory is inited, avoiding the sefgault in position() when select with order by (bug #1133093)
> return index_read_idx(buf, active_index, key, key_len, find_flag);
> }
>
> THIS now fixes the segfault, but causes an assertion indicating we
> havent properly closed something in my_isam; specifically, the
> edges->file table, we have missed a closing ha_index_end(). This is
> where I finally got stuck...
>
> The 'normal' build still passes...
>
> --
> You received this bug notification because you are a member of Open
> Query core, which is subscribed to OQGRAPH.
> https://bugs.launchpad.net/bugs/1133093
>
> Title:
> Crash on ORDER BY in OQGRAPH v3
>
> Status in OQGraph Engine for MariaDB:
> Triaged
>
> Bug description:
> SELECT * FROM graph WHERE latch=1 AND origid=1 AND des...

[Andrew McDonnell (andymc73)]

At your suggestion I took out the first patch and left the second and the problem appears to remain fixed - at least in normal build.

[Andrew McDonnell (andymc73)]

See bug #1213026

[Andrew McDonnell (andymc73)]

I closed this prematurely, Repeated again just now after merging from lp:maria/10.0

Which makes sense looking at the code flow, the first call will still have junk (!)

[Andrew McDonnell (andymc73)]

OK. Updated fix that properly inits ref memory.

Now crashing with a better stacktrace than what we used to get:

Thread 1 (Thread 0x7f2431a4c700 (LWP 11749)):
#0 0x00007f2438ad54ec in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x0000000000ea1f9f in my_write_core (sig=6) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/mysys/stacktrace.c:457
#2 0x000000000081fa19 in handle_fatal_signal (sig=6) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/signal_handler.cc:262
#3 <signal handler called>
#4 0x00007f2437778475 in raise () from /lib/x86_64-linux-gnu/libc.so.6
#5 0x00007f243777b6f0 in abort () from /lib/x86_64-linux-gnu/libc.so.6
#6 0x00007f2437771621 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#7 0x000000000082c300 in handler::ha_external_lock (this=0x2d0fdc8, thd=0x2d008c0, lock_type=2) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/handler.cc:5711
#8 0x00007f24322e78f6 in ha_oqgraph::external_lock (this=0x2d0ca58, thd=0x2d008c0, lock_type=2) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/storage/oqgraph/ha_oqgraph.cc:1113
#9 0x000000000082c38c in handler::ha_external_lock (this=0x2d0ca58, thd=0x2d008c0, lock_type=2) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/handler.cc:5740
#10 0x00000000008fcab6 in unlock_external (thd=0x2d008c0, table=0x2cf8c28, count=1) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/lock.cc:671
#11 0x00000000008fc1f2 in mysql_unlock_read_tables (thd=0x2d008c0, sql_lock=0x2cf8c00) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/lock.cc:430
#12 0x000000000069a3cf in JOIN::join_free (this=0x2cc0c78) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/sql_select.cc:11065
#13 0x00000000006a751d in do_select (join=0x2cc0c78, fields=0x2d04ba0, table=0x0, procedure=0x0) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/sql_select.cc:16513
#14 0x000000000068664f in JOIN::exec_inner (this=0x2cc0c78) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/sql_select.cc:2994
#15 0x0000000000683c27 in JOIN::exec (this=0x2cc0c78) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/sql_select.cc:2292
#16 0x0000000000686ed0 in mysql_select (thd=0x2d008c0, rref_pointer_array=0x2d04d00, tables=0x2cbfa00, wild_num=1, fields=..., conds=0x2cc0618, og_num=1, order=0x2cc0b80, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x2cc0c58, unit=0x2d043b8, select_lex=0x2d04a90) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/sql_select.cc:3222
#17 0x000000000067dabd in handle_select (thd=0x2d008c0, lex=0x2d042f8, result=0x2cc0c58, setup_tables_done_option=0) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/sql_select.cc:371
#18 0x0000000000653a23 in execute_sqlcom_select (thd=0x2d008c0, all_tables=0x2cbfa00) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/sql_parse.cc:5123
#19 0x000000000064c52e in mysql_execute_command (thd=0x2d008c0) at /home/andrew/maria/bz/repo/10.0-oqgraph3-varchar/sql/sql_parse.cc:2518
#20 0x00000000006561c2 in mysql_parse (thd=0x2d008c0, rawbuf=0x2cbf7a8 "SELECT * FROM graph WHERE latch='1' and destid=2 and origid=1 order by seq", length=74, parser_state=0x7f2431a4b660) a...

[Andrew McDonnell (andymc73)]

Finally really fixed it this time...
need to delete hanging cursor when unlocking our handlerton (upload coming shortly)