[MDEV-21018] CPU Spikes to 50% and does not let up with RocksDB enabled Created: 2019-11-09  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - RocksDB
Affects Version/s: 10.2.26, 10.2.29, 10.3.17, 10.3.20, 10.4.7, 10.4.10
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Chris Calender (Inactive) Assignee: Sergei Petrunia
Resolution: Unresolved Votes: 0
Labels: None
Environment:

Encountered on Windows, debugged on Windows.

Attachments: Zip Archive data.zip     PNG File stack trace from debugger.png    

 Description   

When upgrading to 10.4.7 and continuing on through 10.4.10 (and equivalent version of 10.2 and 10.3), if I have the RocksDB plugin enabled:

[mysqld]
 
...
 
plugin_load_add = ha_rocksdb

Then as soon as I start that instance (a service in my case), the CPU usage spikes to 50% and does not let up until I kill the process.

It may dip to 48-49%.

If I start a second instance, they both end up taking ~49-50% each, and the CPU is pegged at 100%.

If I start a third instance, the 3 generally end up using about ~32-33% each, and the CPU is pegged at 100%.

The instances were only using about 32M RAM, and zero activity was occurring on them.

I started Windows profiler, and attached it (and CPU stats gatherer), allowed it to run for 50 seconds, and analyzed. It showed that the CPU usage came from ha_rocksdb.dll.

I then commented out the RocksDB plugin:

#plugin_load_add = ha_rocksdb

Restarted MariaDB.

And then CPU was back to normal, roughly 0% in this case, since there was 0 activity.

Comment: It is easy to remove if you enabled the plugin via the config file: simply remove or comment out the line, as above, and restart MariaDB.

If you enabled it via the command line, then you need to uninstall it via the command line:

UNINSTALL SONAME 'ha_rocksdb';

However, this command is just hanging for me in this situation (i.e., when CPU is pegged out). It is essentially stuck. It did finally complete after about 20 minutes

 Comments   
Comment by Chris Calender (Inactive) [ 2019-11-09 ]

I suspect it started as a result of one of the changes that were incorporated here:

MDEV-19795

Comment by Sergei Petrunia [ 2019-11-09 ]

ccalender,

Did you have any data in RocksDB? Can you paste a hundred or so lines from $DATADIR/#rocksdb/LOG file ?

I started Windows profiler, and attached it (and CPU stats gatherer), allowed it to run for 50 seconds, and analyzed. It showed that the CPU usage came from ha_rocksdb.dll.

Did it show a stack trace (or something similar) where the time was spent? If it did, please post it here

Comment by Chris Calender (Inactive) [ 2019-11-09 ]

Hello psergey, no I do not have any data in RocksDB, nor any rocksdb tables:

mysql> select * from information_schema.tables where engine like 'rocksdb';
 
Empty set (0.20 sec)

Here are the last 100 lines from $DATADIR/#rocksdb/LOG:

rocksdb.db.flush.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
 
rocksdb.sst.batch.size P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
 
2019/11/08-22:13:15.251191 1f78 [db_impl\db_impl.cc:908] SetOptions() on column family [default], inputs:
 
2019/11/08-22:13:15.251191 1f78 [db_impl\db_impl.cc:911] disable_auto_compactions: false
 
2019/11/08-22:13:15.251191 1f78 [db_impl\db_impl.cc:915] [default] SetOptions() succeeded
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:126]                         write_buffer_size: 67108864
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:128]                   max_write_buffer_number: 2
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:131]                          arena_block_size: 8388608
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:133]               memtable_prefix_bloom_ratio: 0.000000
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:135]               memtable_whole_key_filtering: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:138]                   memtable_huge_page_size: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:141]                     max_successive_merges: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:144]                  inplace_update_num_locks: 10000
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:147]                          prefix_extractor: nullptr
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:149]                  disable_auto_compactions: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:151]       soft_pending_compaction_bytes_limit: 68719476736
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:153]       hard_pending_compaction_bytes_limit: 274877906944
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:155]        level0_file_num_compaction_trigger: 4
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:157]            level0_slowdown_writes_trigger: 20
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:159]                level0_stop_writes_trigger: 36
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:161]                      max_compaction_bytes: 1677721600
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:163]                     target_file_size_base: 67108864
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:165]               target_file_size_multiplier: 1
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:167]                  max_bytes_for_level_base: 268435456
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:169]                        snap_refresh_nanos: 100000000
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:171]            max_bytes_for_level_multiplier: 10.000000
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:173]                                       ttl: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:175]               periodic_compaction_seconds: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:189] max_bytes_for_level_multiplier_additional: 1, 1, 1, 1, 1, 1, 1
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:191]         max_sequential_skip_in_iterations: 8
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:193]                      paranoid_file_checks: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:195]                        report_bg_io_stats: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:197]                               compression: 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:201] compaction_options_universal.size_ratio : 1
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:203] compaction_options_universal.min_merge_width : 2
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:205] compaction_options_universal.max_merge_width : -1
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:208] compaction_options_universal.max_size_amplification_percent : 200
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:211] compaction_options_universal.compression_size_percent : -1
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:213] compaction_options_universal.stop_style : 1
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:216] compaction_options_universal.allow_trivial_move : 0
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:220] compaction_options_fifo.max_table_files_size : 1073741824
 
2019/11/08-22:13:15.251191 1f78 [ions\cf_options.cc:222] compaction_options_fifo.allow_compaction : 0
 
2019/11/08-22:13:15.282391 1f78 [db_impl\db_impl.cc:908] SetOptions() on column family [__system__], inputs:
 
2019/11/08-22:13:15.282391 1f78 [db_impl\db_impl.cc:911] disable_auto_compactions: false
 
2019/11/08-22:13:15.282391 1f78 [db_impl\db_impl.cc:915] [__system__] SetOptions() succeeded
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:126]                         write_buffer_size: 67108864
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:128]                   max_write_buffer_number: 2
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:131]                          arena_block_size: 8388608
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:133]               memtable_prefix_bloom_ratio: 0.000000
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:135]               memtable_whole_key_filtering: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:138]                   memtable_huge_page_size: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:141]                     max_successive_merges: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:144]                  inplace_update_num_locks: 10000
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:147]                          prefix_extractor: nullptr
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:149]                  disable_auto_compactions: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:151]       soft_pending_compaction_bytes_limit: 68719476736
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:153]       hard_pending_compaction_bytes_limit: 274877906944
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:155]        level0_file_num_compaction_trigger: 4
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:157]            level0_slowdown_writes_trigger: 20
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:159]                level0_stop_writes_trigger: 36
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:161]                      max_compaction_bytes: 1677721600
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:163]                     target_file_size_base: 67108864
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:165]               target_file_size_multiplier: 1
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:167]                  max_bytes_for_level_base: 268435456
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:169]                        snap_refresh_nanos: 100000000
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:171]            max_bytes_for_level_multiplier: 10.000000
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:173]                                       ttl: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:175]               periodic_compaction_seconds: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:189] max_bytes_for_level_multiplier_additional: 1, 1, 1, 1, 1, 1, 1
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:191]         max_sequential_skip_in_iterations: 8
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:193]                      paranoid_file_checks: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:195]                        report_bg_io_stats: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:197]                               compression: 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:201] compaction_options_universal.size_ratio : 1
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:203] compaction_options_universal.min_merge_width : 2
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:205] compaction_options_universal.max_merge_width : -1
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:208] compaction_options_universal.max_size_amplification_percent : 200
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:211] compaction_options_universal.compression_size_percent : -1
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:213] compaction_options_universal.stop_style : 1
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:216] compaction_options_universal.allow_trivial_move : 0
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:220] compaction_options_fifo.max_table_files_size : 1073741824
 
2019/11/08-22:13:15.282391 1f78 [ions\cf_options.cc:222] compaction_options_fifo.allow_compaction : 0
 
2019/11/08-22:15:12.314198 1f78 [db_impl\db_impl_compaction_flush.cc:1318] [default] Manual flush start.
 
2019/11/08-22:15:12.314198 1f78 [db_impl\db_impl_compaction_flush.cc:1329] [default] Manual flush finished, status: OK
 
2019/11/08-22:15:12.314198 1f78 [db_impl\db_impl_compaction_flush.cc:1318] [__system__] Manual flush start.
 
2019/11/08-22:15:12.314198 1f78 [db_impl\db_impl_write.cc:1576] [__system__] New memtable created with log file: #198. Immutable memtables: 0.
 
2019/11/08-22:15:12.314198 e44 [db_impl\db_impl_compaction_flush.cc:105] [JOB 3] Syncing log #191
 
2019/11/08-22:15:12.314198 e44 (Original Log Time 2019/11/08-22:15:12.314198) [db_impl\db_impl_compaction_flush.cc:2124] Calling FlushMemTableToOutputFile with column family [__system__], flush slots available 1, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
 
2019/11/08-22:15:12.314198 e44 [flush_job.cc:320] [__system__] [JOB 3] Flushing memtable with next log file: 198
 
2019/11/08-22:15:12.314198 e44 EVENT_LOG_v1 {"time_micros": 1573269312314198, "job": 3, "event": "flush_started", "num_memtables": 1, "num_entries": 2, "num_deletes": 0, "total_data_size": 48, "memory_usage": 848, "flush_reason": "Manual Flush"}
 
2019/11/08-22:15:12.314198 e44 [flush_job.cc:349] [__system__] [JOB 3] Level-0 flush table #199: started
 
2019/11/08-22:15:12.329798 e44 EVENT_LOG_v1 {"time_micros": 1573269312329798, "cf_name": "__system__", "job": 3, "event": "table_file_creation", "file_number": 199, "file_size": 966, "table_properties": {"data_size": 56, "index_size": 34, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 0, "index_value_is_delta_encoded": 0, "filter_size": 0, "raw_key_size": 32, "raw_average_key_size": 16, "raw_value_size": 12, "raw_average_value_size": 6, "num_data_blocks": 1, "num_entries": 2, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "__system__", "column_family_id": 1, "comparator": "RocksDB_SE_v3.10", "merge_operator": "Rdb_system_merge_op", "prefix_extractor_name": "nullptr", "property_collectors": "[Rdb_tbl_prop_coll_factory]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; ", "creation_time": 1573269312, "oldest_key_time": 1573269195, "file_creation_time": 1573269312, "__indexstats__": "[...1  records...]"}}
 
2019/11/08-22:15:12.329798 e44 [flush_job.cc:390] [__system__] [JOB 3] Level-0 flush table #199: 966 bytes OK
 
2019/11/08-22:15:12.329798 e44 (Original Log Time 2019/11/08-22:15:12.329798) [memtable_list.cc:382] [__system__] Level-0 commit table #199 started
 
2019/11/08-22:15:12.329798 e44 (Original Log Time 2019/11/08-22:15:12.329798) [memtable_list.cc:430] [__system__] Level-0 commit table #199: memtable #1 done
 
2019/11/08-22:15:12.329798 e44 (Original Log Time 2019/11/08-22:15:12.329798) EVENT_LOG_v1 {"time_micros": 1573269312329798, "job": 3, "event": "flush_finished", "output_compression": "NoCompression", "lsm_state": [3, 1, 0, 0, 0, 0, 0], "immutable_memtables": 0}
 
2019/11/08-22:15:12.329798 e44 (Original Log Time 2019/11/08-22:15:12.329798) [db_impl\db_impl_compaction_flush.cc:205] [__system__] Level summary: files[3 1 0 0 0 0 0] max score 0.75
 
2019/11/08-22:15:12.329798 e44 [db_impl\db_impl_files.cc:353] [JOB 3] Try to delete WAL files size 60, prev total WAL file size 60, number of live WAL files 2.
 
2019/11/08-22:15:12.329798 1f78 [db_impl\db_impl_compaction_flush.cc:1329] [__system__] Manual flush finished, status: OK
 
2019/11/08-22:15:12.329798 1f78 [db_impl\db_impl.cc:394] Shutdown: canceling all background work

Stack trace from debugger (after adding in ha_rocksdb.pdb, and re-creating issue):

Comment by Chris Calender (Inactive) [ 2019-11-10 ]

Sure, it is easy to reproduce. I can every time I enable RocksDB in these newer versions:

plugin_load_add = ha_rocksdb

Then restart and monitor the CPU usage.

I just performed this with a fresh 10.4.10 Win64. Created the datadir fresh usingt mysql_install_db. Then started the instance without ha_rocksdb, and it started fine, and did not consume CPU. Then I stopped, added the above option, and restarted, and the CPU spikes to 50%.

I even disabled rocksdb again (stopped the instance, remove the option, restart, verify rocksdb is not enabled, and CPU is low), then issued:

INSTALL SONAME 'ha_rocksdb';

The command runs fast, and then the CPU spikes to 50% within a few seconds.

Comment by Chris Calender (Inactive) [ 2019-11-10 ]

Not sure if it matter at all, but when I try to uninstall the plugin dynamically:

MariaDB [(none)]> UNINSTALL SONAME 'ha_rocksdb';

While the command takes a long time to complete, during this time, the CPU usage of mysqld drops to 25% (instead of 50%).

MariaDB [(none)]> UNINSTALL SONAME 'ha_rocksdb';
 
Query OK, 0 rows affected (13 min 50.954 sec)

And mysqld CPU usage drops back to near 0% once the command completes.

Comment by Sergei Petrunia [ 2019-11-12 ]

Ok, I had tried with the official 10.4.10 binary:

  • Added plugin_load_add=ha_rocksdb into my.cnf
  • Started the server (CPU load is 0%)
  • Verified the plugin is loaded, created a rocksdb table. Cpu load is still 0%.

Re-ran the same with the provided datadir. The result was the same - CPU load remained 0%.

Comment by Chris Calender (Inactive) [ 2019-11-13 ]

I re-ran the debug session and captured as much info as possible:

CPU Debug Info (let run for ~30 seconds):

Function Name	Total CPU [unit, %]	Self CPU [unit, %]	Module
 
 + mysqld.exe (PID: 9476)	42910 (100.00 %)	0 (0.00 %)	mysqld.exe
 
| - rocksdb::port::WindowsThread::Data::ThreadProc	42868 (99.90 %)	0 (0.00 %)	ha_rocksdb.dll
 
| - ucrtbase.dll!0x0007fef7ffc1ae	42868 (99.90 %)	0 (0.00 %)	ucrtbase.dll
 
| - std::_Func_impl_no_alloc<std::_Binder<std::_Unforced,<lambda_e7fdb2a9eb03358eecf49f1389987e73> >,void>::_Do_call	42865 (99.90 %)	389 (0.91 %)	ha_rocksdb.dll
 
| - rocksdb::port::WinEnvIO::NowMicros	33742 (78.63 %)	9394 (21.89 %)	ha_rocksdb.dll
 
| - rocksdb::InstrumentedCondVar::TimedWait	8512 (19.84 %)	2258 (5.26 %)	ha_rocksdb.dll
 
| - rocksdb::port::CondVar::TimedWait	5976 (13.93 %)	2209 (5.15 %)	ha_rocksdb.dll
 
| - rocksdb::port::WinEnv::NowMicros	217 (0.51 %)	217 (0.51 %)	ha_rocksdb.dll
 
| - rocksdb::`anonymous namespace'::stats_for_report	192 (0.45 %)	192 (0.45 %)	ha_rocksdb.dll
 
| - __security_check_cookie	171 (0.40 %)	171 (0.40 %)	ha_rocksdb.dll
 
| - _Query_perf_counter	96 (0.22 %)	96 (0.22 %)	ha_rocksdb.dll
 
| - rocksdb::InstrumentedCondVar::TimedWaitInternal	85 (0.20 %)	85 (0.20 %)	ha_rocksdb.dll
 
| - _Query_perf_frequency	83 (0.19 %)	83 (0.19 %)	ha_rocksdb.dll
 
| - _Xtime_get_ticks	53 (0.12 %)	53 (0.12 %)	ha_rocksdb.dll
 
| - [Unwalkable]	42 (0.10 %)	0 (0.00 %)	Multiple modules

Then I attached debugger (let run for ~30 seconds) then "break all":

Threads:

Not Flagged		10024	0	Main Thread	Main Thread	sechost.dll!000007fefe98affb
 
Not Flagged		5876	0	Worker Thread	ntdll.dll thread	ntdll.dll!0000000076d0186a
 
Not Flagged		3812	0	Worker Thread	sechost.dll thread	mysqld.exe!NTService::ServiceMain
 
Not Flagged		8688	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!handle_connections_win
 
Not Flagged		2052	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		8528	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		9468	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		5308	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		4592	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		852	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		4804	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		6080	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		3560	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		7152	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		2336	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		5792	0	Worker Thread	mysqld.exe!io_handler_thread	mysqld.exe!os_aio_windows_handler
 
Not Flagged		6664	0	Worker Thread	mysqld.exe!buf_flush_page_cleaner_coordinator	mysqld.exe!os_event::timed_wait
 
Not Flagged		6284	0	Worker Thread	mysqld.exe!lock_wait_timeout_thread	mysqld.exe!os_event::timed_wait
 
Not Flagged		7272	0	Worker Thread	mysqld.exe!srv_error_monitor_thread	mysqld.exe!os_event::timed_wait
 
Not Flagged		1668	0	Worker Thread	mysqld.exe!srv_monitor_thread	mysqld.exe!os_event::timed_wait
 
Not Flagged		9124	0	Worker Thread	mysqld.exe!dict_stats_thread	mysqld.exe!os_event::timed_wait
 
Not Flagged		2564	0	Worker Thread	mysqld.exe!fts_optimize_thread	mysqld.exe!os_event::timed_wait
 
Not Flagged		5020	0	Worker Thread	mysqld.exe!srv_master_thread	mysqld.exe!srv_master_sleep
 
Not Flagged		6248	0	Worker Thread	mysqld.exe!srv_purge_coordinator_thread	[Inline Frame] mysqld.exe!os_event::wait
 
Not Flagged		3700	0	Worker Thread	mysqld.exe!srv_worker_thread	[Inline Frame] mysqld.exe!os_event::wait
 
Not Flagged		7596	0	Worker Thread	mysqld.exe!srv_worker_thread	[Inline Frame] mysqld.exe!os_event::wait
 
Not Flagged		7664	0	Worker Thread	mysqld.exe!srv_worker_thread	[Inline Frame] mysqld.exe!os_event::wait
 
Not Flagged		6036	0	Worker Thread	mysqld.exe!buf_dump_thread	[Inline Frame] mysqld.exe!os_event::wait
 
Not Flagged		10028	0	Worker Thread	mysqld.exe!btr_defragment_thread	mysqld.exe!btr_defragment_thread
 
Not Flagged		6004	0	Worker Thread	mysqld.exe!buf_resize_thread	[Inline Frame] mysqld.exe!os_event::wait
 
Not Flagged		9176	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		7112	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		6656	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		1780	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		7824	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		9704	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		9764	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		8400	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		9080	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		8772	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		5264	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		7364	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		8008	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		2480	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		9308	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		6160	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		6724	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		8584	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		3204	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		4528	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		6500	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		6520	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		5968	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		3656	0	Worker Thread	ntdll.dll thread	ntdll.dll!0000000076d02bba
 
Not Flagged		3456	0	Worker Thread	ntdll.dll thread	ntdll.dll!0000000076d02bba
 
Not Flagged		6792	0	Worker Thread	ucrtbase.dll thread	msvcp140.dll!000007fef811640d
 
Not Flagged		6124	0	Worker Thread	ucrtbase.dll thread	msvcp140.dll!000007fef811640d
 
Not Flagged		4768	0	Worker Thread	ucrtbase.dll thread	msvcp140.dll!000007fef811640d
 
Not Flagged	>	2316	0	Worker Thread	ucrtbase.dll thread	[Inline Frame] ha_rocksdb.dll!std::chrono::steady_clock::now
 
Not Flagged		3696	0	Worker Thread	ucrtbase.dll thread	msvcp140.dll!000007fef80f32ff
 
Not Flagged		9048	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		3732	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait
 
Not Flagged		5184	0	Worker Thread	ucrtbase.dll thread	mysqld.exe!pthread_cond_timedwait

Thread 4768 Call Stack ("mutex") - 1st thread above 2316:

 	[External Code]	
>	[Inline Frame] ha_rocksdb.dll!std::condition_variable::wait(std::unique_lock<std::mutex> &) Line 603	C++		<<-- "mutex"
 
 	ha_rocksdb.dll!rocksdb::ThreadPoolImpl::Impl::BGThread(unsigned __int64 thread_id) Line 197	C++			<<-- "threadpool_imp.cc"
 
 	ha_rocksdb.dll!rocksdb::ThreadPoolImpl::Impl::BGThreadWrapper(void * arg) Line 309	C++				<<-- "threadpool_imp.cc"
 
 	[Inline Frame] ha_rocksdb.dll!std::_Func_class<void>::operator()() Line 1049	C++					<<-- "functional"
 
 	ha_rocksdb.dll!rocksdb::port::WindowsThread::Data::ThreadProc(void * arg) Line 170	C++				<<-- "win_thread.cc"
 
 	[External Code]

Thread 2316 Call Stack ("chrono not found") - thread with the arrow:

>	[Inline Frame] ha_rocksdb.dll!std::chrono::steady_clock::now() Line 575	C++				<<-- "chrono"
 
 	ha_rocksdb.dll!rocksdb::port::WinEnvIO::NowMicros() Line 982	C++					<<-- "env_win.cc"
 
 	[External Code]	
 	[Inline Frame] ha_rocksdb.dll!std::_Func_class<void>::operator()() Line 1049	C++			<<-- "functional"
 
 	ha_rocksdb.dll!rocksdb::port::WindowsThread::Data::ThreadProc(void * arg) Line 170	C++		<<-- "win_thread.cc"
 
 	[External Code]

Thread 3696 Call Stack ("chrono not found") - 1st thread below 2316:

 	[External Code]	
>	[Inline Frame] ha_rocksdb.dll!std::chrono::steady_clock::now() Line 571	C++				<<-- "chrono"
 
 	ha_rocksdb.dll!rocksdb::port::WinEnvIO::NowMicros() Line 982	C++					<<-- "env_win.cc"
 
 	[External Code]	
 	[Inline Frame] ha_rocksdb.dll!std::_Func_class<void>::operator()() Line 1049	C++			<<-- "functional"
 
 	ha_rocksdb.dll!rocksdb::port::WindowsThread::Data::ThreadProc(void * arg) Line 170	C++		<<-- "win_thread.cc"
 
 	[External Code]

Thread 9048 Call Stack ("my_wincond.c") - 2nd thread below 2316:

 	[External Code]	
>	mysqld.exe!pthread_cond_timedwait(_RTL_CONDITION_VARIABLE * cond, _RTL_CRITICAL_SECTION * mutex, const timespec * abstime) Line 85	C	<<-- "my_wincond.c"
 
 	[Inline Frame] ha_rocksdb.dll!inline_mysql_cond_timedwait(st_mysql_cond * that, st_mysql_mutex *) Line 1215	C++				<<-- "mysql_thread.h"
 
 	ha_rocksdb.dll!myrocks::Rdb_background_thread::run() Line 13521	C++										<<-- "ha_rocksdb.cc"
 
 	ha_rocksdb.dll!myrocks::Rdb_thread::thread_func(void * const thread_ptr) Line 35	C++							<<-- "rdb_threads.cc"
 
 	mysqld.exe!pthread_start(void * p) Line 62	C												<<-- "my_winthread.c"
 
 	[External Code]

Thread 3732 Call Stack ("my_wincond.c") - 3rd thread below 2316:

 	[External Code]	
>	mysqld.exe!pthread_cond_timedwait(_RTL_CONDITION_VARIABLE * cond, _RTL_CRITICAL_SECTION * mutex, const timespec * abstime) Line 85	C	<<-- "my_wincond.c"
 
 	[Inline Frame] ha_rocksdb.dll!inline_mysql_cond_timedwait(st_mysql_cond * that, st_mysql_mutex *) Line 1215	C++				<<-- "mysql_thread.h"
 
 	ha_rocksdb.dll!myrocks::Rdb_drop_index_thread::run() Line 11581	C++										<<-- "ha_rocksdb.cc"
 
 	ha_rocksdb.dll!myrocks::Rdb_thread::thread_func(void * const thread_ptr) Line 35	C++							<<-- "rdb_threads.cc"
 
 	mysqld.exe!pthread_start(void * p) Line 62	C												<<-- "my_winthread.c"
 
 	[External Code]

Thread 5184 Call Stack ("my_wincond.c") - 4th and final thread below 2316:

 	[External Code]	
>	mysqld.exe!pthread_cond_timedwait(_RTL_CONDITION_VARIABLE * cond, _RTL_CRITICAL_SECTION * mutex, const timespec * abstime) Line 85	C	<<-- "my_wincond.c"
 
 	[Inline Frame] ha_rocksdb.dll!inline_mysql_cond_timedwait(st_mysql_cond *) Line 1215	C++									<<-- "mysql_thread.h"
 
 	ha_rocksdb.dll!myrocks::Rdb_manual_compaction_thread::run() Line 13614	C++								<<-- "ha_rocksdb.cc"
 
 	ha_rocksdb.dll!myrocks::Rdb_thread::thread_func(void * const thread_ptr) Line 35	C++							<<-- "rdb_threads.cc"
 
 	mysqld.exe!pthread_start(void * p) Line 62	C												<<-- "my_winthread.c"
 
 	[External Code]

Comment by Chris Calender (Inactive) [ 2019-11-13 ]

Well, I guess that helped. I got to searching on some of those functions, and ran across this:

https://github.com/facebook/rocksdb/issues/5552

"100% CPU - Regression for Window 7 in WinEnvIO::NowMicros()"

It sounds like it was fixed here: https://github.com/facebook/rocksdb/pull/5557 (merged on Jul 15, 2019).

10.4.7 (when this started) was released on Jul 31, 2019, so perhaps this fix did not make the merge (of upstream bugs fixed in MDEV-19795) with MariaDB in time.

Generated at Thu Feb 08 09:03:58 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.