From 7dc5d8f8ef8cb4f7a1c188f2200dbe3dd380b8f6 Mon Sep 17 00:00:00 2001 From: Luke Chen Date: Thu, 12 May 2022 17:14:40 +1000 Subject: Import wiredtiger: c2a7ed8278fa29430cd51d5e6ae9815f9fba2850 from branch mongodb-6.0 ref: 799bf81c4b..c2a7ed8278 for: 6.0.0-rc6 WT-9251 Perform log flush before the metadata checkpoint --- src/third_party/wiredtiger/dist/api_data.py | 7 +- src/third_party/wiredtiger/dist/stat_data.py | 1 + src/third_party/wiredtiger/import.data | 2 +- src/third_party/wiredtiger/src/config/config_def.c | 108 ++++++------ src/third_party/wiredtiger/src/conn/conn_api.c | 1 + src/third_party/wiredtiger/src/conn/conn_log.c | 20 ++- .../wiredtiger/src/include/connection.h | 30 ++-- src/third_party/wiredtiger/src/include/stat.h | 1 + .../wiredtiger/src/include/wiredtiger.in | 40 ++--- src/third_party/wiredtiger/src/support/stat.c | 3 + src/third_party/wiredtiger/src/txn/txn_ckpt.c | 14 ++ .../test/suite/test_rollback_to_stable35.py | 182 +++++++++++++++++++++ 12 files changed, 320 insertions(+), 89 deletions(-) create mode 100755 src/third_party/wiredtiger/test/suite/test_rollback_to_stable35.py diff --git a/src/third_party/wiredtiger/dist/api_data.py b/src/third_party/wiredtiger/dist/api_data.py index 5187f93ccda..11632da60ae 100644 --- a/src/third_party/wiredtiger/dist/api_data.py +++ b/src/third_party/wiredtiger/dist/api_data.py @@ -855,7 +855,7 @@ connection_runtime_config = [ type='list', undoc=True, choices=[ 'aggressive_sweep', 'backup_rename', 'checkpoint_reserved_txnid_delay', 'checkpoint_slow', - 'compact_slow', 'failpoint_history_store_delete_key_from_ts', + 'checkpoint_stop', 'compact_slow', 'failpoint_history_store_delete_key_from_ts', 'history_store_checkpoint_delay', 'history_store_search', 'history_store_sweep_race', 'prepare_checkpoint_delay', 'split_1', 'split_2', 'split_3', 'split_4', 'split_5', 'split_6', 'split_7', 'tiered_flush_finish']), @@ -989,6 +989,11 @@ wiredtiger_open_log_configuration = [ the maximum size of log files''', min='100KB', # !!! Must match WT_LOG_FILE_MIN max='2GB'), # !!! Must match WT_LOG_FILE_MAX + Config('force_write_wait', '0', r''' + enable code that interrupts the usual timing of flushing the log from + the internal log server thread with a goal of uncovering race conditions. + This option is intended for use with internal stress testing of WiredTiger.''', + min='1', max='60', undoc=True), Config('path', '"."', r''' the name of a directory into which log files are written. The directory must already exist. If the value is not an absolute path, diff --git a/src/third_party/wiredtiger/dist/stat_data.py b/src/third_party/wiredtiger/dist/stat_data.py index c48682685c4..b02b8512af5 100644 --- a/src/third_party/wiredtiger/dist/stat_data.py +++ b/src/third_party/wiredtiger/dist/stat_data.py @@ -577,6 +577,7 @@ conn_stats = [ TxnStat('txn_checkpoint_time_min', 'transaction checkpoint min time (msecs)', 'no_clear,no_scale'), TxnStat('txn_checkpoint_time_recent', 'transaction checkpoint most recent time (msecs)', 'no_clear,no_scale'), TxnStat('txn_checkpoint_time_total', 'transaction checkpoint total time (msecs)', 'no_clear,no_scale'), + TxnStat('txn_checkpoint_stop_stress_active', 'transaction checkpoint stop timing stress active', 'no_clear,no_scale'), TxnStat('txn_commit', 'transactions committed'), TxnStat('txn_fail_cache', 'transaction failures due to history store'), TxnStat('txn_pinned_checkpoint_range', 'transaction range of IDs currently pinned by a checkpoint', 'no_clear,no_scale'), diff --git a/src/third_party/wiredtiger/import.data b/src/third_party/wiredtiger/import.data index 9abd14bc727..59a1ce570a6 100644 --- a/src/third_party/wiredtiger/import.data +++ b/src/third_party/wiredtiger/import.data @@ -2,5 +2,5 @@ "vendor": "wiredtiger", "github": "wiredtiger/wiredtiger.git", "branch": "mongodb-6.0", - "commit": "799bf81c4b6546b4edccaaa985077de8e69a4e99" + "commit": "c2a7ed8278fa29430cd51d5e6ae9815f9fba2850" } diff --git a/src/third_party/wiredtiger/src/config/config_def.c b/src/third_party/wiredtiger/src/config/config_def.c index 53c7f8847db..f07124e852c 100644 --- a/src/third_party/wiredtiger/src/config/config_def.c +++ b/src/third_party/wiredtiger/src/config/config_def.c @@ -161,7 +161,8 @@ static const WT_CONFIG_CHECK confchk_WT_CONNECTION_reconfigure[] = { {"timing_stress_for_test", "list", NULL, "choices=[\"aggressive_sweep\",\"backup_rename\"," "\"checkpoint_reserved_txnid_delay\",\"checkpoint_slow\"," - "\"compact_slow\",\"failpoint_history_store_delete_key_from_ts\"," + "\"checkpoint_stop\",\"compact_slow\"," + "\"failpoint_history_store_delete_key_from_ts\"," "\"history_store_checkpoint_delay\",\"history_store_search\"," "\"history_store_sweep_race\",\"prepare_checkpoint_delay\"," "\"split_1\",\"split_2\",\"split_3\",\"split_4\",\"split_5\"," @@ -819,6 +820,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_log_subconfigs[] = { {"archive", "boolean", NULL, NULL, NULL, 0}, {"compressor", "string", NULL, NULL, NULL, 0}, {"enabled", "boolean", NULL, NULL, NULL, 0}, {"file_max", "int", NULL, "min=100KB,max=2GB", NULL, 0}, + {"force_write_wait", "int", NULL, "min=1,max=60", NULL, 0}, {"os_cache_dirty_pct", "int", NULL, "min=0,max=100", NULL, 0}, {"path", "string", NULL, NULL, NULL, 0}, {"prealloc", "boolean", NULL, NULL, NULL, 0}, {"recover", "string", NULL, "choices=[\"error\",\"on\"]", NULL, 0}, @@ -879,7 +881,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open[] = { {"in_memory", "boolean", NULL, NULL, NULL, 0}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, - {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 10}, + {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 11}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"mmap", "boolean", NULL, NULL, NULL, 0}, {"mmap_all", "boolean", NULL, NULL, NULL, 0}, {"multiprocess", "boolean", NULL, NULL, NULL, 0}, @@ -901,7 +903,8 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open[] = { {"timing_stress_for_test", "list", NULL, "choices=[\"aggressive_sweep\",\"backup_rename\"," "\"checkpoint_reserved_txnid_delay\",\"checkpoint_slow\"," - "\"compact_slow\",\"failpoint_history_store_delete_key_from_ts\"," + "\"checkpoint_stop\",\"compact_slow\"," + "\"failpoint_history_store_delete_key_from_ts\"," "\"history_store_checkpoint_delay\",\"history_store_search\"," "\"history_store_sweep_race\",\"prepare_checkpoint_delay\"," "\"split_1\",\"split_2\",\"split_3\",\"split_4\",\"split_5\"," @@ -962,7 +965,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_all[] = { {"in_memory", "boolean", NULL, NULL, NULL, 0}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, - {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 10}, + {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 11}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"mmap", "boolean", NULL, NULL, NULL, 0}, {"mmap_all", "boolean", NULL, NULL, NULL, 0}, {"multiprocess", "boolean", NULL, NULL, NULL, 0}, @@ -984,7 +987,8 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_all[] = { {"timing_stress_for_test", "list", NULL, "choices=[\"aggressive_sweep\",\"backup_rename\"," "\"checkpoint_reserved_txnid_delay\",\"checkpoint_slow\"," - "\"compact_slow\",\"failpoint_history_store_delete_key_from_ts\"," + "\"checkpoint_stop\",\"compact_slow\"," + "\"failpoint_history_store_delete_key_from_ts\"," "\"history_store_checkpoint_delay\",\"history_store_search\"," "\"history_store_sweep_race\",\"prepare_checkpoint_delay\"," "\"split_1\",\"split_2\",\"split_3\",\"split_4\",\"split_5\"," @@ -1043,7 +1047,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_basecfg[] = { {"history_store", "category", NULL, NULL, confchk_wiredtiger_open_history_store_subconfigs, 1}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, - {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 10}, + {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 11}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"mmap", "boolean", NULL, NULL, NULL, 0}, {"mmap_all", "boolean", NULL, NULL, NULL, 0}, {"multiprocess", "boolean", NULL, NULL, NULL, 0}, @@ -1065,7 +1069,8 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_basecfg[] = { {"timing_stress_for_test", "list", NULL, "choices=[\"aggressive_sweep\",\"backup_rename\"," "\"checkpoint_reserved_txnid_delay\",\"checkpoint_slow\"," - "\"compact_slow\",\"failpoint_history_store_delete_key_from_ts\"," + "\"checkpoint_stop\",\"compact_slow\"," + "\"failpoint_history_store_delete_key_from_ts\"," "\"history_store_checkpoint_delay\",\"history_store_search\"," "\"history_store_sweep_race\",\"prepare_checkpoint_delay\"," "\"split_1\",\"split_2\",\"split_3\",\"split_4\",\"split_5\"," @@ -1122,7 +1127,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_usercfg[] = { {"history_store", "category", NULL, NULL, confchk_wiredtiger_open_history_store_subconfigs, 1}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, - {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 10}, + {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 11}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"mmap", "boolean", NULL, NULL, NULL, 0}, {"mmap_all", "boolean", NULL, NULL, NULL, 0}, {"multiprocess", "boolean", NULL, NULL, NULL, 0}, @@ -1144,7 +1149,8 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_usercfg[] = { {"timing_stress_for_test", "list", NULL, "choices=[\"aggressive_sweep\",\"backup_rename\"," "\"checkpoint_reserved_txnid_delay\",\"checkpoint_slow\"," - "\"compact_slow\",\"failpoint_history_store_delete_key_from_ts\"," + "\"checkpoint_stop\",\"compact_slow\"," + "\"failpoint_history_store_delete_key_from_ts\"," "\"history_store_checkpoint_delay\",\"history_store_search\"," "\"history_store_sweep_race\",\"prepare_checkpoint_delay\"," "\"split_1\",\"split_2\",\"split_3\",\"split_4\",\"split_5\"," @@ -1485,16 +1491,17 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "close_scan_interval=10),hash=(buckets=512,dhandle_buckets=512)," "hazard_max=1000,history_store=(file_max=0),in_memory=false," "io_capacity=(total=0),json_output=[],log=(archive=true," - "compressor=,enabled=false,file_max=100MB,os_cache_dirty_pct=0," - "path=\".\",prealloc=true,recover=on,remove=true,zero_fill=false)" - ",lsm_manager=(merge=true,worker_thread_max=4),mmap=true," - "mmap_all=false,multiprocess=false,operation_timeout_ms=0," - "operation_tracking=(enabled=false,path=\".\"),readonly=false," - "salvage=false,session_max=100,session_scratch_max=2MB," - "session_table_cache=true,shared_cache=(chunk=10MB,name=,quota=0," - "reserve=0,size=500MB),statistics=none,statistics_log=(json=false" - ",on_close=false,path=\".\",sources=,timestamp=\"%b %d %H:%M:%S\"" - ",wait=0),tiered_manager=(threads_max=8,threads_min=1,wait=0)," + "compressor=,enabled=false,file_max=100MB,force_write_wait=0," + "os_cache_dirty_pct=0,path=\".\",prealloc=true,recover=on," + "remove=true,zero_fill=false),lsm_manager=(merge=true," + "worker_thread_max=4),mmap=true,mmap_all=false,multiprocess=false" + ",operation_timeout_ms=0,operation_tracking=(enabled=false," + "path=\".\"),readonly=false,salvage=false,session_max=100," + "session_scratch_max=2MB,session_table_cache=true," + "shared_cache=(chunk=10MB,name=,quota=0,reserve=0,size=500MB)," + "statistics=none,statistics_log=(json=false,on_close=false," + "path=\".\",sources=,timestamp=\"%b %d %H:%M:%S\",wait=0)," + "tiered_manager=(threads_max=8,threads_min=1,wait=0)," "tiered_storage=(auth_token=,bucket=,bucket_prefix=," "cache_directory=,local_retention=300,name=," "object_target_size=10M),timing_stress_for_test=," @@ -1526,16 +1533,17 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "close_scan_interval=10),hash=(buckets=512,dhandle_buckets=512)," "hazard_max=1000,history_store=(file_max=0),in_memory=false," "io_capacity=(total=0),json_output=[],log=(archive=true," - "compressor=,enabled=false,file_max=100MB,os_cache_dirty_pct=0," - "path=\".\",prealloc=true,recover=on,remove=true,zero_fill=false)" - ",lsm_manager=(merge=true,worker_thread_max=4),mmap=true," - "mmap_all=false,multiprocess=false,operation_timeout_ms=0," - "operation_tracking=(enabled=false,path=\".\"),readonly=false," - "salvage=false,session_max=100,session_scratch_max=2MB," - "session_table_cache=true,shared_cache=(chunk=10MB,name=,quota=0," - "reserve=0,size=500MB),statistics=none,statistics_log=(json=false" - ",on_close=false,path=\".\",sources=,timestamp=\"%b %d %H:%M:%S\"" - ",wait=0),tiered_manager=(threads_max=8,threads_min=1,wait=0)," + "compressor=,enabled=false,file_max=100MB,force_write_wait=0," + "os_cache_dirty_pct=0,path=\".\",prealloc=true,recover=on," + "remove=true,zero_fill=false),lsm_manager=(merge=true," + "worker_thread_max=4),mmap=true,mmap_all=false,multiprocess=false" + ",operation_timeout_ms=0,operation_tracking=(enabled=false," + "path=\".\"),readonly=false,salvage=false,session_max=100," + "session_scratch_max=2MB,session_table_cache=true," + "shared_cache=(chunk=10MB,name=,quota=0,reserve=0,size=500MB)," + "statistics=none,statistics_log=(json=false,on_close=false," + "path=\".\",sources=,timestamp=\"%b %d %H:%M:%S\",wait=0)," + "tiered_manager=(threads_max=8,threads_min=1,wait=0)," "tiered_storage=(auth_token=,bucket=,bucket_prefix=," "cache_directory=,local_retention=300,name=," "object_target_size=10M),timing_stress_for_test=," @@ -1566,16 +1574,17 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "close_idle_time=30,close_scan_interval=10),hash=(buckets=512," "dhandle_buckets=512),hazard_max=1000,history_store=(file_max=0)," "io_capacity=(total=0),json_output=[],log=(archive=true," - "compressor=,enabled=false,file_max=100MB,os_cache_dirty_pct=0," - "path=\".\",prealloc=true,recover=on,remove=true,zero_fill=false)" - ",lsm_manager=(merge=true,worker_thread_max=4),mmap=true," - "mmap_all=false,multiprocess=false,operation_timeout_ms=0," - "operation_tracking=(enabled=false,path=\".\"),readonly=false," - "salvage=false,session_max=100,session_scratch_max=2MB," - "session_table_cache=true,shared_cache=(chunk=10MB,name=,quota=0," - "reserve=0,size=500MB),statistics=none,statistics_log=(json=false" - ",on_close=false,path=\".\",sources=,timestamp=\"%b %d %H:%M:%S\"" - ",wait=0),tiered_manager=(threads_max=8,threads_min=1,wait=0)," + "compressor=,enabled=false,file_max=100MB,force_write_wait=0," + "os_cache_dirty_pct=0,path=\".\",prealloc=true,recover=on," + "remove=true,zero_fill=false),lsm_manager=(merge=true," + "worker_thread_max=4),mmap=true,mmap_all=false,multiprocess=false" + ",operation_timeout_ms=0,operation_tracking=(enabled=false," + "path=\".\"),readonly=false,salvage=false,session_max=100," + "session_scratch_max=2MB,session_table_cache=true," + "shared_cache=(chunk=10MB,name=,quota=0,reserve=0,size=500MB)," + "statistics=none,statistics_log=(json=false,on_close=false," + "path=\".\",sources=,timestamp=\"%b %d %H:%M:%S\",wait=0)," + "tiered_manager=(threads_max=8,threads_min=1,wait=0)," "tiered_storage=(auth_token=,bucket=,bucket_prefix=," "cache_directory=,local_retention=300,name=," "object_target_size=10M),timing_stress_for_test=," @@ -1605,16 +1614,17 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "close_idle_time=30,close_scan_interval=10),hash=(buckets=512," "dhandle_buckets=512),hazard_max=1000,history_store=(file_max=0)," "io_capacity=(total=0),json_output=[],log=(archive=true," - "compressor=,enabled=false,file_max=100MB,os_cache_dirty_pct=0," - "path=\".\",prealloc=true,recover=on,remove=true,zero_fill=false)" - ",lsm_manager=(merge=true,worker_thread_max=4),mmap=true," - "mmap_all=false,multiprocess=false,operation_timeout_ms=0," - "operation_tracking=(enabled=false,path=\".\"),readonly=false," - "salvage=false,session_max=100,session_scratch_max=2MB," - "session_table_cache=true,shared_cache=(chunk=10MB,name=,quota=0," - "reserve=0,size=500MB),statistics=none,statistics_log=(json=false" - ",on_close=false,path=\".\",sources=,timestamp=\"%b %d %H:%M:%S\"" - ",wait=0),tiered_manager=(threads_max=8,threads_min=1,wait=0)," + "compressor=,enabled=false,file_max=100MB,force_write_wait=0," + "os_cache_dirty_pct=0,path=\".\",prealloc=true,recover=on," + "remove=true,zero_fill=false),lsm_manager=(merge=true," + "worker_thread_max=4),mmap=true,mmap_all=false,multiprocess=false" + ",operation_timeout_ms=0,operation_tracking=(enabled=false," + "path=\".\"),readonly=false,salvage=false,session_max=100," + "session_scratch_max=2MB,session_table_cache=true," + "shared_cache=(chunk=10MB,name=,quota=0,reserve=0,size=500MB)," + "statistics=none,statistics_log=(json=false,on_close=false," + "path=\".\",sources=,timestamp=\"%b %d %H:%M:%S\",wait=0)," + "tiered_manager=(threads_max=8,threads_min=1,wait=0)," "tiered_storage=(auth_token=,bucket=,bucket_prefix=," "cache_directory=,local_retention=300,name=," "object_target_size=10M),timing_stress_for_test=," diff --git a/src/third_party/wiredtiger/src/conn/conn_api.c b/src/third_party/wiredtiger/src/conn/conn_api.c index 799b199bfb2..83df335f041 100644 --- a/src/third_party/wiredtiger/src/conn/conn_api.c +++ b/src/third_party/wiredtiger/src/conn/conn_api.c @@ -2242,6 +2242,7 @@ __wt_timing_stress_config(WT_SESSION_IMPL *session, const char *cfg[]) {"backup_rename", WT_TIMING_STRESS_BACKUP_RENAME}, {"checkpoint_reserved_txnid_delay", WT_TIMING_STRESS_CHECKPOINT_RESERVED_TXNID_DELAY}, {"checkpoint_slow", WT_TIMING_STRESS_CHECKPOINT_SLOW}, + {"checkpoint_stop", WT_TIMING_STRESS_CHECKPOINT_STOP}, {"compact_slow", WT_TIMING_STRESS_COMPACT_SLOW}, {"failpoint_history_delete_key_from_ts", WT_TIMING_STRESS_FAILPOINT_HISTORY_STORE_DELETE_KEY_FROM_TS}, diff --git a/src/third_party/wiredtiger/src/conn/conn_log.c b/src/third_party/wiredtiger/src/conn/conn_log.c index 40abcbc91fa..f48f2f6512c 100644 --- a/src/third_party/wiredtiger/src/conn/conn_log.c +++ b/src/third_party/wiredtiger/src/conn/conn_log.c @@ -310,6 +310,10 @@ __wt_logmgr_config(WT_SESSION_IMPL *session, const char **cfg, bool reconfig) if (cval.val != 0) conn->log_prealloc = 1; + WT_RET(__wt_config_gets(session, cfg, "log.force_write_wait", &cval)); + if (cval.val != 0) + conn->log_force_write_wait = (uint32_t)cval.val; + /* * Note it's meaningless to reconfigure this value during runtime, it only matters on create * before recovery runs. @@ -837,20 +841,22 @@ __log_server(void *arg) WT_DECL_RET; WT_LOG *log; WT_SESSION_IMPL *session; + uint64_t force_write_time_start, force_write_timediff; uint64_t time_start, time_stop, timediff; bool did_work, signalled; session = arg; conn = S2C(session); log = conn->log; + force_write_timediff = 0; signalled = false; /* - * Set this to the number of milliseconds we want to run remove and pre-allocation. Start it so - * that we run on the first time through. + * Set this to the number of milliseconds we want to run log force write, remove and + * pre-allocation. Start it so that we run on the first time through. */ timediff = WT_THOUSAND; - time_start = __wt_clock(session); + force_write_time_start = time_start = __wt_clock(session); /* * The log server thread does a variety of work. It forces out any buffered log writes. It @@ -868,8 +874,11 @@ __log_server(void *arg) * buffer may need to wait for the write_lsn to advance in the case of a synchronous buffer. * We end up with a hang. */ - WT_ERR_ERROR_OK(__wt_log_force_write(session, 0, &did_work), EBUSY, false); - + if (conn->log_force_write_wait == 0 || + force_write_timediff >= conn->log_force_write_wait * WT_THOUSAND) { + WT_ERR_ERROR_OK(__wt_log_force_write(session, 0, &did_work), EBUSY, false); + force_write_time_start = __wt_clock(session); + } /* * We don't want to remove or pre-allocate files as often as we want to force out log * buffers. Only do it once per second or if the condition was signalled. @@ -907,6 +916,7 @@ __log_server(void *arg) __wt_cond_auto_wait_signal(session, conn->log_cond, did_work, NULL, &signalled); time_stop = __wt_clock(session); timediff = WT_CLOCKDIFF_MS(time_stop, time_start); + force_write_timediff = WT_CLOCKDIFF_MS(time_stop, force_write_time_start); } if (0) { diff --git a/src/third_party/wiredtiger/src/include/connection.h b/src/third_party/wiredtiger/src/include/connection.h index 326d9f90033..7926c8bd5e7 100644 --- a/src/third_party/wiredtiger/src/include/connection.h +++ b/src/third_party/wiredtiger/src/include/connection.h @@ -488,6 +488,7 @@ struct __wt_connection_impl { uint32_t log_cursors; /* Log cursor count */ wt_off_t log_dirty_max; /* Log dirty system cache max size */ wt_off_t log_file_max; /* Log file max size */ + uint32_t log_force_write_wait; /* Log force write wait configuration */ const char *log_path; /* Logging path format */ uint32_t log_prealloc; /* Log file pre-allocation */ uint16_t log_req_max; /* Max required log version */ @@ -588,20 +589,21 @@ struct __wt_connection_impl { #define WT_TIMING_STRESS_BACKUP_RENAME 0x00002u #define WT_TIMING_STRESS_CHECKPOINT_RESERVED_TXNID_DELAY 0x00004u #define WT_TIMING_STRESS_CHECKPOINT_SLOW 0x00008u -#define WT_TIMING_STRESS_COMPACT_SLOW 0x00010u -#define WT_TIMING_STRESS_FAILPOINT_HISTORY_STORE_DELETE_KEY_FROM_TS 0x00020u -#define WT_TIMING_STRESS_HS_CHECKPOINT_DELAY 0x00040u -#define WT_TIMING_STRESS_HS_SEARCH 0x00080u -#define WT_TIMING_STRESS_HS_SWEEP 0x00100u -#define WT_TIMING_STRESS_PREPARE_CHECKPOINT_DELAY 0x00200u -#define WT_TIMING_STRESS_SPLIT_1 0x00400u -#define WT_TIMING_STRESS_SPLIT_2 0x00800u -#define WT_TIMING_STRESS_SPLIT_3 0x01000u -#define WT_TIMING_STRESS_SPLIT_4 0x02000u -#define WT_TIMING_STRESS_SPLIT_5 0x04000u -#define WT_TIMING_STRESS_SPLIT_6 0x08000u -#define WT_TIMING_STRESS_SPLIT_7 0x10000u -#define WT_TIMING_STRESS_TIERED_FLUSH_FINISH 0x20000u +#define WT_TIMING_STRESS_CHECKPOINT_STOP 0x00010u +#define WT_TIMING_STRESS_COMPACT_SLOW 0x00020u +#define WT_TIMING_STRESS_FAILPOINT_HISTORY_STORE_DELETE_KEY_FROM_TS 0x00040u +#define WT_TIMING_STRESS_HS_CHECKPOINT_DELAY 0x00080u +#define WT_TIMING_STRESS_HS_SEARCH 0x00100u +#define WT_TIMING_STRESS_HS_SWEEP 0x00200u +#define WT_TIMING_STRESS_PREPARE_CHECKPOINT_DELAY 0x00400u +#define WT_TIMING_STRESS_SPLIT_1 0x00800u +#define WT_TIMING_STRESS_SPLIT_2 0x01000u +#define WT_TIMING_STRESS_SPLIT_3 0x02000u +#define WT_TIMING_STRESS_SPLIT_4 0x04000u +#define WT_TIMING_STRESS_SPLIT_5 0x08000u +#define WT_TIMING_STRESS_SPLIT_6 0x10000u +#define WT_TIMING_STRESS_SPLIT_7 0x20000u +#define WT_TIMING_STRESS_TIERED_FLUSH_FINISH 0x40000u /* AUTOMATIC FLAG VALUE GENERATION STOP 64 */ uint64_t timing_stress_flags; diff --git a/src/third_party/wiredtiger/src/include/stat.h b/src/third_party/wiredtiger/src/include/stat.h index df2915742eb..9d1cf91fe3e 100644 --- a/src/third_party/wiredtiger/src/include/stat.h +++ b/src/third_party/wiredtiger/src/include/stat.h @@ -828,6 +828,7 @@ struct __wt_connection_stats { int64_t txn_checkpoint_prep_total; int64_t txn_checkpoint_scrub_target; int64_t txn_checkpoint_scrub_time; + int64_t txn_checkpoint_stop_stress_active; int64_t txn_checkpoint_time_total; int64_t txn_checkpoint; int64_t txn_checkpoint_obsolete_applied; diff --git a/src/third_party/wiredtiger/src/include/wiredtiger.in b/src/third_party/wiredtiger/src/include/wiredtiger.in index 6c77ab92bb2..5f61b805c77 100644 --- a/src/third_party/wiredtiger/src/include/wiredtiger.in +++ b/src/third_party/wiredtiger/src/include/wiredtiger.in @@ -6358,59 +6358,61 @@ extern int wiredtiger_extension_terminate(WT_CONNECTION *connection); #define WT_STAT_CONN_TXN_CHECKPOINT_SCRUB_TARGET 1494 /*! transaction: transaction checkpoint scrub time (msecs) */ #define WT_STAT_CONN_TXN_CHECKPOINT_SCRUB_TIME 1495 +/*! transaction: transaction checkpoint stop timing stress active */ +#define WT_STAT_CONN_TXN_CHECKPOINT_STOP_STRESS_ACTIVE 1496 /*! transaction: transaction checkpoint total time (msecs) */ -#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_TOTAL 1496 +#define WT_STAT_CONN_TXN_CHECKPOINT_TIME_TOTAL 1497 /*! transaction: transaction checkpoints */ -#define WT_STAT_CONN_TXN_CHECKPOINT 1497 +#define WT_STAT_CONN_TXN_CHECKPOINT 1498 /*! transaction: transaction checkpoints due to obsolete pages */ -#define WT_STAT_CONN_TXN_CHECKPOINT_OBSOLETE_APPLIED 1498 +#define WT_STAT_CONN_TXN_CHECKPOINT_OBSOLETE_APPLIED 1499 /*! * transaction: transaction checkpoints skipped because database was * clean */ -#define WT_STAT_CONN_TXN_CHECKPOINT_SKIPPED 1499 +#define WT_STAT_CONN_TXN_CHECKPOINT_SKIPPED 1500 /*! transaction: transaction failures due to history store */ -#define WT_STAT_CONN_TXN_FAIL_CACHE 1500 +#define WT_STAT_CONN_TXN_FAIL_CACHE 1501 /*! * transaction: transaction fsync calls for checkpoint after allocating * the transaction ID */ -#define WT_STAT_CONN_TXN_CHECKPOINT_FSYNC_POST 1501 +#define WT_STAT_CONN_TXN_CHECKPOINT_FSYNC_POST 1502 /*! * transaction: transaction fsync duration for checkpoint after * allocating the transaction ID (usecs) */ -#define WT_STAT_CONN_TXN_CHECKPOINT_FSYNC_POST_DURATION 1502 +#define WT_STAT_CONN_TXN_CHECKPOINT_FSYNC_POST_DURATION 1503 /*! transaction: transaction range of IDs currently pinned */ -#define WT_STAT_CONN_TXN_PINNED_RANGE 1503 +#define WT_STAT_CONN_TXN_PINNED_RANGE 1504 /*! transaction: transaction range of IDs currently pinned by a checkpoint */ -#define WT_STAT_CONN_TXN_PINNED_CHECKPOINT_RANGE 1504 +#define WT_STAT_CONN_TXN_PINNED_CHECKPOINT_RANGE 1505 /*! transaction: transaction range of timestamps currently pinned */ -#define WT_STAT_CONN_TXN_PINNED_TIMESTAMP 1505 +#define WT_STAT_CONN_TXN_PINNED_TIMESTAMP 1506 /*! transaction: transaction range of timestamps pinned by a checkpoint */ -#define WT_STAT_CONN_TXN_PINNED_TIMESTAMP_CHECKPOINT 1506 +#define WT_STAT_CONN_TXN_PINNED_TIMESTAMP_CHECKPOINT 1507 /*! * transaction: transaction range of timestamps pinned by the oldest * active read timestamp */ -#define WT_STAT_CONN_TXN_PINNED_TIMESTAMP_READER 1507 +#define WT_STAT_CONN_TXN_PINNED_TIMESTAMP_READER 1508 /*! * transaction: transaction range of timestamps pinned by the oldest * timestamp */ -#define WT_STAT_CONN_TXN_PINNED_TIMESTAMP_OLDEST 1508 +#define WT_STAT_CONN_TXN_PINNED_TIMESTAMP_OLDEST 1509 /*! transaction: transaction read timestamp of the oldest active reader */ -#define WT_STAT_CONN_TXN_TIMESTAMP_OLDEST_ACTIVE_READ 1509 +#define WT_STAT_CONN_TXN_TIMESTAMP_OLDEST_ACTIVE_READ 1510 /*! transaction: transaction rollback to stable currently running */ -#define WT_STAT_CONN_TXN_ROLLBACK_TO_STABLE_RUNNING 1510 +#define WT_STAT_CONN_TXN_ROLLBACK_TO_STABLE_RUNNING 1511 /*! transaction: transaction walk of concurrent sessions */ -#define WT_STAT_CONN_TXN_WALK_SESSIONS 1511 +#define WT_STAT_CONN_TXN_WALK_SESSIONS 1512 /*! transaction: transactions committed */ -#define WT_STAT_CONN_TXN_COMMIT 1512 +#define WT_STAT_CONN_TXN_COMMIT 1513 /*! transaction: transactions rolled back */ -#define WT_STAT_CONN_TXN_ROLLBACK 1513 +#define WT_STAT_CONN_TXN_ROLLBACK 1514 /*! transaction: update conflicts */ -#define WT_STAT_CONN_TXN_UPDATE_CONFLICT 1514 +#define WT_STAT_CONN_TXN_UPDATE_CONFLICT 1515 /*! * @} diff --git a/src/third_party/wiredtiger/src/support/stat.c b/src/third_party/wiredtiger/src/support/stat.c index 54e1480dff5..5187beac9cc 100644 --- a/src/third_party/wiredtiger/src/support/stat.c +++ b/src/third_party/wiredtiger/src/support/stat.c @@ -1556,6 +1556,7 @@ static const char *const __stats_connection_desc[] = { "transaction: transaction checkpoint prepare total time (msecs)", "transaction: transaction checkpoint scrub dirty target", "transaction: transaction checkpoint scrub time (msecs)", + "transaction: transaction checkpoint stop timing stress active", "transaction: transaction checkpoint total time (msecs)", "transaction: transaction checkpoints", "transaction: transaction checkpoints due to obsolete pages", @@ -2112,6 +2113,7 @@ __wt_stat_connection_clear_single(WT_CONNECTION_STATS *stats) /* not clearing txn_checkpoint_prep_total */ /* not clearing txn_checkpoint_scrub_target */ /* not clearing txn_checkpoint_scrub_time */ + /* not clearing txn_checkpoint_stop_stress_active */ /* not clearing txn_checkpoint_time_total */ stats->txn_checkpoint = 0; stats->txn_checkpoint_obsolete_applied = 0; @@ -2688,6 +2690,7 @@ __wt_stat_connection_aggregate(WT_CONNECTION_STATS **from, WT_CONNECTION_STATS * to->txn_checkpoint_prep_total += WT_STAT_READ(from, txn_checkpoint_prep_total); to->txn_checkpoint_scrub_target += WT_STAT_READ(from, txn_checkpoint_scrub_target); to->txn_checkpoint_scrub_time += WT_STAT_READ(from, txn_checkpoint_scrub_time); + to->txn_checkpoint_stop_stress_active += WT_STAT_READ(from, txn_checkpoint_stop_stress_active); to->txn_checkpoint_time_total += WT_STAT_READ(from, txn_checkpoint_time_total); to->txn_checkpoint += WT_STAT_READ(from, txn_checkpoint); to->txn_checkpoint_obsolete_applied += WT_STAT_READ(from, txn_checkpoint_obsolete_applied); diff --git a/src/third_party/wiredtiger/src/txn/txn_ckpt.c b/src/third_party/wiredtiger/src/txn/txn_ckpt.c index 84140d18c18..cb4cebae43c 100644 --- a/src/third_party/wiredtiger/src/txn/txn_ckpt.c +++ b/src/third_party/wiredtiger/src/txn/txn_ckpt.c @@ -1020,6 +1020,15 @@ __txn_checkpoint(WT_SESSION_IMPL *session, const char *cfg[]) */ WT_ERR(__wt_txn_commit(session, NULL)); + /* + * Flush all the logs that are generated during the checkpoint. It is possible that checkpoint + * may include the changes that are written in parallel by an eviction. To have a consistent + * view of the data, make sure that all the logs are flushed to disk before the checkpoint is + * complete. + */ + if (FLD_ISSET(conn->log_flags, WT_CONN_LOG_ENABLED)) + WT_ERR(__wt_log_flush(session, WT_LOG_FSYNC)); + /* * Ensure that the metadata changes are durable before the checkpoint is resolved. Do this by * either checkpointing the metadata or syncing the log file. Recovery relies on the checkpoint @@ -1047,6 +1056,11 @@ __txn_checkpoint(WT_SESSION_IMPL *session, const char *cfg[]) WT_WITH_DHANDLE(session, WT_SESSION_META_DHANDLE(session), ret = __wt_txn_checkpoint_log(session, false, WT_TXN_LOG_CKPT_SYNC, NULL)); + WT_STAT_CONN_SET(session, txn_checkpoint_stop_stress_active, 1); + /* Wait prior to flush the checkpoint stop log record. */ + __checkpoint_timing_stress(session, WT_TIMING_STRESS_CHECKPOINT_STOP, &tsp); + WT_STAT_CONN_SET(session, txn_checkpoint_stop_stress_active, 0); + /* * Now that the metadata is stable, re-open the metadata file for regular eviction by clearing * the checkpoint_pinned flag. diff --git a/src/third_party/wiredtiger/test/suite/test_rollback_to_stable35.py b/src/third_party/wiredtiger/test/suite/test_rollback_to_stable35.py new file mode 100755 index 00000000000..218a4330251 --- /dev/null +++ b/src/third_party/wiredtiger/test/suite/test_rollback_to_stable35.py @@ -0,0 +1,182 @@ +#!/usr/bin/env python +# +# Public Domain 2014-present MongoDB, Inc. +# Public Domain 2008-2014 WiredTiger, Inc. +# +# This is free and unencumbered software released into the public domain. +# +# Anyone is free to copy, modify, publish, use, compile, sell, or +# distribute this software, either in source code form or as a compiled +# binary, for any purpose, commercial or non-commercial, and by any +# means. +# +# In jurisdictions that recognize copyright laws, the author or authors +# of this software dedicate any and all copyright interest in the +# software to the public domain. We make this dedication for the benefit +# of the public at large and to the detriment of our heirs and +# successors. We intend this dedication to be an overt act of +# relinquishment in perpetuity of all present and future rights to this +# software under copyright law. +# +# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, +# EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF +# MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. +# IN NO EVENT SHALL THE AUTHORS BE LIABLE FOR ANY CLAIM, DAMAGES OR +# OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, +# ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR +# OTHER DEALINGS IN THE SOFTWARE. + +import wttest, threading, time +from wtdataset import SimpleDataSet +from wtthread import checkpoint_thread +from helper import simulate_crash_restart +from wiredtiger import stat +from helper import copy_wiredtiger_home +from wtscenario import make_scenarios +from test_rollback_to_stable01 import test_rollback_to_stable_base + +# test_rollback_to_stable35.py +# Test that log is flushed for all writes that occurred in the checkpoint. +class test_rollback_to_stable35(test_rollback_to_stable_base): + + format_values = [ + ('column', dict(key_format='r', value_format='S')), + ('column_fix', dict(key_format='r', value_format='8t')), + ('row_integer', dict(key_format='i', value_format='S')), + ] + + scenarios = make_scenarios(format_values) + + def large_updates(self, uri_1, uri_2, value, ds_1, ds_2, nrows): + # Update a large number of records. + session = self.session + cursor_1 = session.open_cursor(uri_1) + cursor_2 = session.open_cursor(uri_2) + for i in range(1, nrows + 1): + session.begin_transaction() + cursor_1[ds_1.key(i)] = value + cursor_2[ds_2.key(i)] = value + session.commit_transaction() + cursor_1.close() + cursor_2.close() + + def check(self, check_value, uri_1, uri_2, nrows): + session = self.session + session.begin_transaction() + cursor_1 = session.open_cursor(uri_1) + cursor_2 = session.open_cursor(uri_2) + count = 0 + for k, v in cursor_1: + self.assertEqual(v, check_value) + count += 1 + self.assertEqual(count, nrows) + count = 0 + for k, v in cursor_2: + self.assertEqual(v, check_value) + count += 1 + self.assertEqual(count, nrows) + session.commit_transaction() + cursor_1.close() + cursor_2.close() + + def conn_config(self): + config = 'cache_size=50MB,statistics=(all),log=(enabled,force_write_wait=60),timing_stress_for_test=[checkpoint_slow, checkpoint_stop]' + return config + + def test_rollback_to_stable(self): + nrows = 10 + + # Create two tables. + uri_1 = "table:rollback_to_stable35_1" + ds_1 = SimpleDataSet( + self, uri_1, 0, key_format=self.key_format, value_format=self.value_format) + ds_1.populate() + + uri_2 = "table:rollback_to_stable35_2" + ds_2 = SimpleDataSet( + self, uri_2, 0, key_format=self.key_format, value_format=self.value_format) + ds_2.populate() + + if self.value_format == '8t': + valuea = 97 + valueb = 98 + valuec = 99 + else: + valuea = "aaaaa" * 100 + valueb = "bbbbb" * 100 + valuec = "ccccc" * 100 + + self.large_updates(uri_1, uri_2, valuea, ds_1, ds_2, nrows) + self.check(valuea, uri_1, uri_2, nrows) + + # Start a long running transaction and keep it open. + session_2 = self.conn.open_session() + session_2.begin_transaction() + + self.large_updates(uri_1, uri_2, valueb, ds_1, ds_2, nrows) + self.check(valueb, uri_1, uri_2, nrows) + + # Create a checkpoint thread + done = threading.Event() + ckpt = checkpoint_thread(self.conn, done) + try: + ckpt.start() + # Wait for checkpoint to start before committing. + ckpt_started = 0 + while not ckpt_started: + stat_cursor = self.session.open_cursor('statistics:', None, None) + ckpt_started = stat_cursor[stat.conn.txn_checkpoint_running][2] + stat_cursor.close() + time.sleep(1) + + self.large_updates(uri_1, uri_2, valuec, ds_1, ds_2, nrows) + self.check(valuec, uri_1, uri_2, nrows) + + # Evict the data. + self.evict_cursor(uri_1, nrows, valuec) + + # Wait for checkpoint stop timing stress to copy the database. + ckpt_stop_timing_stress = 0 + while not ckpt_stop_timing_stress: + time.sleep(1) + stat_cursor = self.session.open_cursor('statistics:', None, None) + ckpt_stop_timing_stress = stat_cursor[stat.conn.txn_checkpoint_stop_stress_active][2] + stat_cursor.close() + + copy_wiredtiger_home(self, '.', "RESTART") + + finally: + done.set() + ckpt.join() + self.session.checkpoint() + + # Clear all running transactions before rollback to stable. + session_2.commit_transaction() + session_2.close() + + # Open the new directory + self.close_conn() + self.conn_config = 'cache_size=50MB,statistics=(all),log=(enabled)' + conn = self.setUpConnectionOpen("RESTART") + self.session = self.setUpSessionOpen(conn) + + self.check(valuec, uri_1, uri_2, nrows) + + stat_cursor = self.session.open_cursor('statistics:', None, None) + calls = stat_cursor[stat.conn.txn_rts][2] + upd_aborted = stat_cursor[stat.conn.txn_rts_upd_aborted][2] + hs_removed = stat_cursor[stat.conn.txn_rts_hs_removed][2] + keys_removed = stat_cursor[stat.conn.txn_rts_keys_removed][2] + keys_restored = stat_cursor[stat.conn.txn_rts_keys_restored][2] + pages_visited = stat_cursor[stat.conn.txn_rts_pages_visited][2] + stat_cursor.close() + + self.assertEqual(calls, 0) + self.assertEqual(keys_removed, 0) + self.assertEqual(keys_restored, 0) + self.assertEqual(pages_visited, 0) + self.assertEqual(upd_aborted, 0) + self.assertGreaterEqual(hs_removed, 0) + +if __name__ == '__main__': + wttest.run() -- cgit v1.2.1