Uploaded image for project: 'WiredTiger'
  1. WiredTiger
  2. WT-2915

Test format hung in long tester

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      Found another hung test-format run.

      Git revision: 1c4d75fe92716950d50a05ddceda5b0cfbedbb17

      Config:

      ############################################
      #  RUN PARAMETERS
      ############################################
      abort=0
      auto_throttle=1
      backups=0
      bitcnt=5
      bloom=1
      bloom_bit_count=30
      bloom_hash_count=17
      bloom_oldest=0
      cache=23
      checkpoints=1
      checksum=off
      chunk_size=10
      compaction=1
      compression=none
      data_extend=0
      data_source=table
      delete_pct=10
      dictionary=0
      direct_io=0
      encryption=none
      evict_max=1
      file_type=fix
      firstfit=1
      huffman_key=0
      huffman_value=0
      in_memory=0
      insert_pct=38
      internal_key_truncation=1
      internal_page_max=10
      isolation=read-committed
      key_gap=10
      key_max=105
      key_min=30
      leaf_page_max=15
      leak_memory=0
      logging=1
      logging_archive=0
      logging_compression=none
      logging_prealloc=0
      lsm_worker_threads=3
      merge_max=16
      mmap=1
      ops=500000
      prefix_compression=1
      prefix_compression_min=5
      quiet=1
      repeat_data_pct=27
      reverse=0
      rows=20000
      runs=1
      rebalance=1
      salvage=1
      split_pct=44
      statistics=0
      statistics_server=0
      threads=4
      timer=20
      transaction-frequency=25
      value_max=3200
      value_min=5
      verify=1
      wiredtiger_config=
      write_pct=24
      ############################################
      

      Traces:

      (gdb) thread apply all bt
       
      Thread 11 (Thread 0x7f86fc875700 (LWP 13333)):
      #0  0x00007f86fecfea82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x00007f86ff41be7f in __wt_cond_wait_signal (session=0x1b69df0, cond=0x1bb3100, usecs=100000, signalled=0x7f86fc874e9f) at ../src/os_posix/os_mtx_cond.c:71
      #2  0x00007f86ff3aecb9 in __wt_cond_wait (session=0x1b69df0, cond=0x1bb3100, usecs=100000) at ../src/include/misc.i:18
      #3  0x00007f86ff3b0302 in __log_file_server (arg=0x1b69df0) at ../src/conn/conn_log.c:520
      #4  0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #5  0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 10 (Thread 0x7f86fc074700 (LWP 13334)):
      #0  0x00007f86fecfea82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x00007f86ff41be7f in __wt_cond_wait_signal (session=0x1b6a130, cond=0x1bb3190, usecs=1000000, signalled=0x7f86fc073eaf) at ../src/os_posix/os_mtx_cond.c:71
      #2  0x00007f86ff45a079 in __wt_cond_auto_wait_signal (session=0x1b6a130, cond=0x1bb3190, progress=false, signalled=0x7f86fc073eaf) at ../src/support/cond_auto.c:97
      #3  0x00007f86ff45a163 in __wt_cond_auto_wait (session=0x1b6a130, cond=0x1bb3190, progress=false) at ../src/support/cond_auto.c:120
      #4  0x00007f86ff3b0b9e in __log_wrlsn_server (arg=0x1b6a130) at ../src/conn/conn_log.c:736
      #5  0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #6  0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 9 (Thread 0x7f86fb873700 (LWP 13335)):
      #0  0x00007f86fecfea82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x00007f86ff41be7f in __wt_cond_wait_signal (session=0x1b6a470, cond=0x1bb35d0, usecs=1000000, signalled=0x7f86fb872ebe) at ../src/os_posix/os_mtx_cond.c:71
      #2  0x00007f86ff45a079 in __wt_cond_auto_wait_signal (session=0x1b6a470, cond=0x1bb35d0, progress=false, signalled=0x7f86fb872ebe) at ../src/support/cond_auto.c:97
      #3  0x00007f86ff3b0dcf in __log_server (arg=0x1b6a470) at ../src/conn/conn_log.c:843
      #4  0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #5  0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 8 (Thread 0x7f86fb072700 (LWP 13336)):
      #0  0x00007f86fecfea82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x00007f86ff41be7f in __wt_cond_wait_signal (session=0x1b6aaf0, cond=0x1b68700, usecs=1000000, signalled=0x7f86fb071e8f) at ../src/os_posix/os_mtx_cond.c:71
      #2  0x00007f86ff45a079 in __wt_cond_auto_wait_signal (session=0x1b6aaf0, cond=0x1b68700, progress=false, signalled=0x7f86fb071e8f) at ../src/support/cond_auto.c:97
      #3  0x00007f86ff45a163 in __wt_cond_auto_wait (session=0x1b6aaf0, cond=0x1b68700, progress=false) at ../src/support/cond_auto.c:120
      #4  0x00007f86ff3e5da2 in __wt_evict_thread_run (session=0x1b6aaf0, thread=0x1bc8090) at ../src/evict/evict_lru.c:249
      #5  0x00007f86ff465c39 in __wt_thread_run (arg=0x1bc8090) at ../src/support/thread_group.c:25
      #6  0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #7  0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 7 (Thread 0x7f86fa871700 (LWP 13337)):
      #0  0x00007f86fecfea82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x00007f86ff41be7f in __wt_cond_wait_signal (session=0x1b6ae30, cond=0x1bedbc0, usecs=10000000, signalled=0x7f86fa870eaf) at ../src/os_posix/os_mtx_cond.c:71
      #2  0x00007f86ff3b4c1e in __wt_cond_wait (session=0x1b6ae30, cond=0x1bedbc0, usecs=10000000) at ../src/include/misc.i:18
      #3  0x00007f86ff3b55ee in __sweep_server (arg=0x1b6ae30) at ../src/conn/conn_sweep.c:272
      #4  0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #5  0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 6 (Thread 0x7f86fa070700 (LWP 13338)):
      #0  0x00007f86fed00f4d in __lll_lock_wait () from /lib64/libpthread.so.0
      #1  0x00007f86fecfcd02 in _L_lock_791 () from /lib64/libpthread.so.0
      #2  0x00007f86fecfcc08 in pthread_mutex_lock () from /lib64/libpthread.so.0
      #3  0x00007f86ff468c2d in __wt_spin_lock (session=0x1b6b4b0, t=0x1b54c80) at ../src/include/mutex.i:159
      #4  0x00007f86ff46bbf5 in __txn_checkpoint (session=0x1b6b4b0, cfg=0x7f86fa06ed10) at ../src/txn/txn_ckpt.c:648
      #5  0x00007f86ff46cc6b in __wt_txn_checkpoint (session=0x1b6b4b0, cfg=0x7f86fa06ed10) at ../src/txn/txn_ckpt.c:908
      #6  0x00007f86ff456263 in __session_checkpoint (wt_session=0x1b6b4b0, config=0x0) at ../src/session/session_api.c:1578
      #7  0x0000000000405f68 in ops (arg=0x1bf8170) at ../../../test/format/ops.c:533
      ---Type <return> to continue, or q <return> to quit---
      #8  0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #9  0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 5 (Thread 0x7f86f986f700 (LWP 13339)):
      #0  0x00007f86fecfea82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x00007f86ff41be7f in __wt_cond_wait_signal (session=0x1b6be70, cond=0x1bc7fe0, usecs=10000, signalled=0x7f86f986d68f) at ../src/os_posix/os_mtx_cond.c:71
      #2  0x00007f86ff3e568c in __wt_cond_wait (session=0x1b6be70, cond=0x1bc7fe0, usecs=10000) at ../src/include/misc.i:18
      #3  0x00007f86ff3e9d47 in __wt_cache_eviction_worker (session=0x1b6be70, busy=false, pct_full=84) at ../src/evict/evict_lru.c:1806
      #4  0x00007f86ff359650 in __wt_cache_eviction_check (session=0x1b6be70, busy=false, didworkp=0x0) at ../src/include/cache.i:355
      #5  0x00007f86ff35a68a in __cursor_enter (session=0x1b6be70) at ../src/include/cursor.i:56
      #6  0x00007f86ff35a76b in __curfile_enter (cbt=0x7f86ec04b660) at ../src/include/cursor.i:90
      #7  0x00007f86ff35a91c in __cursor_func_init (cbt=0x7f86ec04b660, reenter=true) at ../src/include/cursor.i:263
      #8  0x00007f86ff35b3b0 in __wt_btcur_search (cbt=0x7f86ec04b660) at ../src/btree/bt_cursor.c:337
      #9  0x00007f86ff3c03bf in __curfile_search (cursor=0x7f86ec04b660) at ../src/cursor/cur_file.c:200
      #10 0x00007f86ff43ef1a in __schema_open_table (session=0x1b6be70, name=0x1b54516 "wt", namelen=2, ok_incomplete=false, tablep=0x7f86f986db00) at ../src/schema/schema_open.c:444
      #11 0x00007f86ff43fac9 in __wt_schema_open_table (session=0x1b6be70, name=0x1b54516 "wt", namelen=2, ok_incomplete=false, tablep=0x7f86f986db00) at ../src/schema/schema_open.c:630
      #12 0x00007f86ff43c5e6 in __schema_add_table (session=0x1b6be70, name=0x1b54516 "wt", namelen=2, ok_incomplete=false, tablep=0x7f86f986db60) at ../src/schema/schema_list.c:28
      #13 0x00007f86ff43c9e8 in __wt_schema_get_table (session=0x1b6be70, name=0x1b54516 "wt", namelen=2, ok_incomplete=false, tablep=0x7f86f986dbc8) at ../src/schema/schema_list.c:100
      #14 0x00007f86ff3e3540 in __wt_curtable_open (session=0x1b6be70, uri=0x1b54510 "table:wt", owner=0x0, cfg=0x7f86f986dd10, cursorp=0x7f86f986dd30) at ../src/cursor/cur_table.c:888
      #15 0x00007f86ff44a0ee in __session_open_cursor_int (session=0x1b6be70, uri=0x1b54510 "table:wt", owner=0x0, other=0x0, cfg=0x7f86f986dd10, cursorp=0x7f86f986dd30) at ../src/session/session_api.c:295
      #16 0x00007f86ff44abd2 in __session_open_cursor (wt_session=0x1b6be70, uri=0x1b54510 "table:wt", to_dup=0x0, config=0x40dfc7 "overwrite", cursorp=0x7f86f986de48) at ../src/session/session_api.c:430
      #17 0x0000000000405d16 in ops (arg=0x1bf81f0) at ../../../test/format/ops.c:489
      #18 0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #19 0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 4 (Thread 0x7f86f906e700 (LWP 13340)):
      #0  0x00007f86fecfea82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x00007f86ff41be7f in __wt_cond_wait_signal (session=0x1b6bb30, cond=0x1bc7fe0, usecs=10000, signalled=0x7f86f906cacf) at ../src/os_posix/os_mtx_cond.c:71
      #2  0x00007f86ff3e568c in __wt_cond_wait (session=0x1b6bb30, cond=0x1bc7fe0, usecs=10000) at ../src/include/misc.i:18
      #3  0x00007f86ff3e9d47 in __wt_cache_eviction_worker (session=0x1b6bb30, busy=false, pct_full=84) at ../src/evict/evict_lru.c:1806
      #4  0x00007f86ff359650 in __wt_cache_eviction_check (session=0x1b6bb30, busy=false, didworkp=0x0) at ../src/include/cache.i:355
      #5  0x00007f86ff3599b6 in __wt_txn_idle_cache_check (session=0x1b6bb30) at ../src/include/txn.i:313
      #6  0x00007f86ff35a8ed in __cursor_func_init (cbt=0x7f86e0087250, reenter=true) at ../src/include/cursor.i:260
      #7  0x00007f86ff35b794 in __wt_btcur_search_near (cbt=0x7f86e0087250, exactp=0x7f86f906cd44) at ../src/btree/bt_cursor.c:427
      #8  0x00007f86ff3c0849 in __curfile_search_near (cursor=0x7f86e0087250, exact=0x7f86f906cd44) at ../src/cursor/cur_file.c:222
      #9  0x0000000000406df1 in read_row (cursor=0x7f86e0087250, key=0x7f86f906ce10, value=0x7f86f906cde0, keyno=117652) at ../../../test/format/ops.c:851
      #10 0x00000000004066ff in ops (arg=0x1bf8270) at ../../../test/format/ops.c:686
      #11 0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #12 0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 3 (Thread 0x7f86f886d700 (LWP 13341)):
      #0  0x00007f86fecfea82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x00007f86ff41be7f in __wt_cond_wait_signal (session=0x1b6b7f0, cond=0x1bc7fe0, usecs=10000, signalled=0x7f86f886babf) at ../src/os_posix/os_mtx_cond.c:71
      #2  0x00007f86ff3e568c in __wt_cond_wait (session=0x1b6b7f0, cond=0x1bc7fe0, usecs=10000) at ../src/include/misc.i:18
      #3  0x00007f86ff3e9d47 in __wt_cache_eviction_worker (session=0x1b6b7f0, busy=false, pct_full=84) at ../src/evict/evict_lru.c:1806
      #4  0x00007f86ff359650 in __wt_cache_eviction_check (session=0x1b6b7f0, busy=false, didworkp=0x0) at ../src/include/cache.i:355
      #5  0x00007f86ff3599b6 in __wt_txn_idle_cache_check (session=0x1b6b7f0) at ../src/include/txn.i:313
      #6  0x00007f86ff35a8ed in __cursor_func_init (cbt=0x7f86e40adbb0, reenter=true) at ../src/include/cursor.i:260
      #7  0x00007f86ff35cbd4 in __wt_btcur_update (cbt=0x7f86e40adbb0) at ../src/btree/bt_cursor.c:774
      #8  0x00007f86ff3c1620 in __curfile_update (cursor=0x7f86e40adbb0) at ../src/cursor/cur_file.c:284
      #9  0x00000000004073f7 in col_update (cursor=0x7f86e40adbb0, key=0x7f86f886be10, value=0x7f86f886bde0, keyno=113523) at ../../../test/format/ops.c:1104
      #10 0x0000000000406649 in ops (arg=0x1bf82f0) at ../../../test/format/ops.c:671
      #11 0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      ---Type <return> to continue, or q <return> to quit---
      #12 0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 2 (Thread 0x7f86f3fff700 (LWP 13342)):
      #0  0x00007f86fed00f4d in __lll_lock_wait () from /lib64/libpthread.so.0
      #1  0x00007f86fecfcd02 in _L_lock_791 () from /lib64/libpthread.so.0
      #2  0x00007f86fecfcc08 in pthread_mutex_lock () from /lib64/libpthread.so.0
      #3  0x00007f86ff456f8d in __wt_spin_lock (session=0x1b6b170, t=0x1b54c40) at ../src/include/mutex.i:159
      #4  0x00007f86ff457b7e in __wt_session_compact (wt_session=0x1b6b170, uri=0x1b54510 "table:wt", config=0x0) at ../src/session/session_compact.c:292
      #5  0x000000000040278b in compact (arg=0x0) at ../../../test/format/compact.c:66
      #6  0x00007f86fecfadc5 in start_thread () from /lib64/libpthread.so.0
      #7  0x00007f86fea27c9d in clone () from /lib64/libc.so.6
       
      Thread 1 (Thread 0x7f86ff8ce740 (LWP 13325)):
      #0  0x00007f86fe9eeeed in nanosleep () from /lib64/libc.so.6
      #1  0x00007f86fea1fae4 in usleep () from /lib64/libc.so.6
      #2  0x00000000004051f8 in wts_ops (lastrun=0) at ../../../test/format/ops.c:172
      #3  0x00000000004088a6 in main (argc=7, argv=0x7ffc5e2b04a0) at ../../../test/format/t.c:216
      (gdb)
      

      Probably the most interesting thing from the traces is that the checkpoint (thread 6) is blocked behind a cursor open (thread 5).

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                keith.bostic Keith Bostic
                Reporter:
                david.hows David Hows
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: