LRU restore does not perform well

[monty solomon]

I manually started a LRU restore. It is still running after 30 minutes.

Innotop

Cmd ID State User Host DB Time Query
Query 1126 executing root localhost 32:52.408 select * from information_schema.XTRADB_ADMIN_COMMAND /*!XTRA_LRU_RESTORE*/

Server version: 5.5.38-35.2-log Percona Server (GPL), Release 35.2, Revision 674
CentOS release 6.5 (Final)
Linux 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

             total used free shared buffers cached
Mem: 15370896 8104280 7266616 0 70504 3213636

[monty solomon (monty+launchpad)]

innodb_buffer_pool_instances 4
innodb_buffer_pool_populate OFF
innodb_buffer_pool_restore_at_startup 0
innodb_buffer_pool_shm_checksum ON
innodb_buffer_pool_shm_key 0
innodb_buffer_pool_size 11811160064

[monty solomon (monty+launchpad)]

show global status

Variable_name Value
Aborted_clients 793
Aborted_connects 0
Binlog_cache_disk_use 0
Binlog_cache_use 0
Binlog_stmt_cache_disk_use 0
Binlog_stmt_cache_use 6745
Bytes_received 200814946
Bytes_sent 11288757
Com_admin_commands 1593
Com_assign_to_keycache 0
Com_alter_db 0
Com_alter_db_upgrade 0
Com_alter_event 0
Com_alter_function 0
Com_alter_procedure 0
Com_alter_server 0
Com_alter_table 115
Com_alter_tablespace 0
Com_analyze 0
Com_begin 102484
Com_binlog 0
Com_call_procedure 0
Com_change_db 211
Com_change_master 2
Com_check 64
Com_checksum 0
Com_commit 102484
Com_create_db 1
Com_create_event 0
Com_create_function 0
Com_create_index 0
Com_create_procedure 1
Com_create_server 0
Com_create_table 42
Com_create_trigger 0
Com_create_udf 0
Com_create_user 0
Com_create_view 0
Com_dealloc_sql 24
Com_delete 2812
Com_delete_multi 0
Com_do 0
Com_drop_db 1
Com_drop_event 0
Com_drop_function 0
Com_drop_index 0
Com_drop_procedure 2
Com_drop_server 0
Com_drop_table 1
Com_drop_trigger 0
Com_drop_user 0
Com_drop_view 0
Com_empty_query 0
Com_execute_sql 24
Com_flush 18
Com_grant 0
Com_ha_close 0
Com_ha_open 0
Com_ha_read 0
Com_help 0
Com_insert 95351
Com_insert_select 1
Com_install_plugin 0
Com_kill 0
Com_load 0
Com_lock_tables 0
Com_optimize 0
Com_preload_keys 0
Com_prepare_sql 24
Com_purge 0
Com_purge_before_date 0
Com_release_savepoint 0
Com_rename_table 0
Com_rename_user 0
Com_repair 0
Com_replace 0
Com_replace_select 0
Com_reset 0
Com_resignal 0
Com_revoke 0
Com_revoke_all 0
Com_rollback 0
Com_rollback_to_savepoint 0
Com_savepoint 0
Com_select 3465
Com_set_option 5137
Com_signal 0
Com_show_authors 0
Com_show_binlog_events 0
Com_show_binlogs 0
Com_show_charsets 0
Com_show_client_statistics 0
Com_show_collations 0
Com_show_contributors 0
Com_show_create_db 0
Com_show_create_event 0
Com_show_create_func 0
Com_show_create_proc 0
Com_show_create_table 199
Com_show_create_trigger 0
Com_show_databases 2
Com_show_engine_logs 0
Com_show_engine_mutex 0
Com_show_engine_status 0
Com_show_events 0
Com_show_errors 0
Com_show_fields 17
Com_show_function_status 0
Com_show_grants 0
Com_show_index_statistics 0
Com_show_keys 0
Com_show_master_status 87
Com_show_open_tables 0
Com_show_plugins 18
Com_show_privileges 0
Com_show_procedure_status 0
Com_show_processlist 201
Com_show_profile 0
Com_show_profiles 0
Com_show_relaylog_events 0
Com_show_slave_hosts 0
Com_show_slave_status 486
Com_show_slave_status_nolock 0
Com_show_status 721
Com_show_storage_engines 0
Com_show_table_statistics 0
Com_show_table_status 0
Com_show_tables 12
Com_show_temporary_tables 0
Com_show_thread_statistics 0
Com_show_triggers 0
Com_show_user_statistics 0
Com_show_variables 1201
Com_show_warnings 0
Com_slave_start 1
Com_slave_stop 0
Com_stmt_close 24
Com_stmt_execute 24
Com_stmt_fetch 0
Com_stmt_prepare 24
Com_stmt_reprepare 0
Com_stmt_reset 0
Com_stmt_send_long_data 0
Com_truncate 4
Com_uninstall_plugin 0
Com_unlock_tables 1
Com_update 90281
Com_update_multi 1
Com_xa_commit 0
Com_xa_end 0
Com_xa_prepare 0
Com_xa_recover 0
Com_xa_rollback 0
Com_xa_start 0
Compression OFF
Connections 1366
Created_tmp_disk_tables 207
Created_tmp_files 8
Created_tmp_tables 1886
Delayed_errors 0
Delayed_i...

[monty solomon (monty+launchpad)]

mysql> select * from information_schema.XTRADB_ADMIN_COMMAND /*!XTRA_LRU_RESTORE*/;
+---------------------------------+
| result_message |
+---------------------------------+
| XTRA_LRU_RESTORE was succeeded. |
+---------------------------------+
1 row in set (43 min 25.29 sec)

[Valerii Kravchuk (valerii-kravchuk)]

Why do you think that restoring 11G (potentially) of InnoDB pages (that may still be random) during 43 minutes is "slow"? Any benchmarks fro random I/O of 16K pages on your disks maybe, or the output of pt-summary script?

Yes, it is not fast, but we know nothing about your disks to claim its slower than one may expect.

[monty solomon (monty+launchpad)]

Please improve the documentation

http://www.percona.com/doc/percona-server/5.5/management/innodb_lru_dump_restore.html

This special feature of Percona Server enables the buffer pool to be restored to its pre-shutdown state in a matter of minutes.

It is safe to enable automatically, and we have not found any performance regressions in it.

[monty solomon (monty+launchpad)]

I ran some fio benchmarks.

random writes

fio_test_file: (groupid=0, jobs=16): err= 0: pid=28006: Thu Jul 31 20:08:44 2014
  write: io=2513.7MB, bw=14296KB/s, iops=893 , runt=180007msec
    clat (usec): min=905 , max=3779.3K, avg=17898.56, stdev=113343.28
     lat (usec): min=906 , max=3779.3K, avg=17902.24, stdev=113343.22
    clat percentiles (usec):
     | 1.00th=[ 988], 5.00th=[ 1064], 10.00th=[ 1096], 20.00th=[ 1176],
     | 30.00th=[ 1288], 40.00th=[ 1432], 50.00th=[ 1704], 60.00th=[ 2192],
     | 70.00th=[ 3344], 80.00th=[ 6944], 90.00th=[18816], 95.00th=[38656],
     | 99.00th=[460800], 99.50th=[749568], 99.90th=[1744896], 99.95th=[2244608],
     | 99.99th=[2768896]
    bw (KB/s) : min= 4, max= 4672, per=8.70%, avg=1244.28, stdev=1276.62
    lat (usec) : 1000=1.38%
    lat (msec) : 2=55.66%, 4=15.81%, 10=11.21%, 20=6.51%, 50=5.33%
    lat (msec) : 100=1.80%, 250=0.95%, 500=0.48%, 750=0.37%, 1000=0.18%
    lat (msec) : 2000=0.25%, >=2000=0.07%
  cpu : usr=0.03%, sys=0.25%, ctx=162974, majf=0, minf=432
  IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued : total=r=0/w=160836/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
  WRITE: io=2513.7MB, aggrb=14295KB/s, minb=14295KB/s, maxb=14295KB/s, mint=180007msec, maxt=180007msec

Disk stats (read/write):
    md0: ios=3/161372, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=0/40637, aggrmerge=0/76, aggrticks=4/733975, aggrin_queue=733976, aggrutil=86.50%
  xvdg: ios=0/47767, merge=0/74, ticks=0/2029021, in_queue=2029018, util=86.50%
  xvdh: ios=0/38299, merge=0/80, ticks=0/158279, in_queue=158277, util=27.64%
  xvdi: ios=3/38293, merge=0/60, ticks=16/74085, in_queue=74099, util=20.61%
  xvdf: ios=0/38190, merge=0/92, ticks=0/674515, in_queue=674510, util=47.29%

[monty solomon (monty+launchpad)]

random reads

fio_test_file: (groupid=0, jobs=16): err= 0: pid=28369: Thu Jul 31 20:12:42 2014
  read : io=22959MB, bw=130579KB/s, iops=8161 , runt=180045msec
    clat (usec): min=4 , max=272917 , avg=1956.20, stdev=10334.97
     lat (usec): min=5 , max=272918 , avg=1957.03, stdev=10334.97
    clat percentiles (usec):
     | 1.00th=[ 5], 5.00th=[ 5], 10.00th=[ 5], 20.00th=[ 5],
     | 30.00th=[ 5], 40.00th=[ 5], 50.00th=[ 6], 60.00th=[ 6],
     | 70.00th=[ 6], 80.00th=[ 8], 90.00th=[ 430], 95.00th=[ 636],
     | 99.00th=[59136], 99.50th=[71168], 99.90th=[99840], 99.95th=[112128],
     | 99.99th=[144384]
    bw (KB/s) : min= 205, max=1625632, per=6.31%, avg=8244.22, stdev=70815.90
    lat (usec) : 10=81.70%, 20=2.20%, 50=0.22%, 100=0.06%, 250=0.04%
    lat (usec) : 500=7.53%, 750=3.85%, 1000=0.25%
    lat (msec) : 2=0.11%, 4=0.06%, 10=0.16%, 20=0.20%, 50=1.98%
    lat (msec) : 100=1.52%, 250=0.10%, 500=0.01%
  cpu : usr=0.12%, sys=0.49%, ctx=239491, majf=0, minf=518
  IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued : total=r=1469381/w=0/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=22959MB, aggrb=130578KB/s, minb=130578KB/s, maxb=130578KB/s, mint=180045msec, maxt=180045msec

Disk stats (read/write):
    md0: ios=231559/3, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=57908/0, aggrmerge=0/0, aggrticks=716872/1, aggrin_queue=716870, aggrutil=100.00%
  xvdg: ios=74724/0, merge=0/0, ticks=83960/0, in_queue=83956, util=31.21%
  xvdh: ios=53923/0, merge=0/0, ticks=2727374/0, in_queue=2727372, util=100.00%
  xvdi: ios=51871/0, merge=0/0, ticks=32311/0, in_queue=32306, util=15.82%
  xvdf: ios=51117/3, merge=0/0, ticks=23843/4, in_queue=23846, util=12.05%

[monty solomon (monty+launchpad)]

Mixed random reads and writes

fio_test_file: (groupid=0, jobs=16): err= 0: pid=31502: Thu Jul 31 20:35:01 2014
  read : io=1556.8MB, bw=8854.7KB/s, iops=553 , runt=180028msec
    clat (usec): min=298 , max=1826.1K, avg=16447.98, stdev=26927.50
     lat (usec): min=299 , max=1826.1K, avg=16448.84, stdev=26927.50
    clat percentiles (usec):
     | 1.00th=[ 334], 5.00th=[ 382], 10.00th=[ 524], 20.00th=[ 1176],
     | 30.00th=[ 4448], 40.00th=[ 7328], 50.00th=[ 9792], 60.00th=[13120],
     | 70.00th=[17536], 80.00th=[24704], 90.00th=[38656], 95.00th=[54528],
     | 99.00th=[100864], 99.50th=[128512], 99.90th=[272384], 99.95th=[337920],
     | 99.99th=[1236992]
    bw (KB/s) : min= 12, max= 1600, per=6.33%, avg=560.55, stdev=194.36
  write: io=1554.9MB, bw=8844.2KB/s, iops=552 , runt=180028msec
    clat (usec): min=900 , max=1250.2K, avg=12461.58, stdev=23317.58
     lat (usec): min=904 , max=1250.2K, avg=12465.08, stdev=23317.58
    clat percentiles (usec):
     | 1.00th=[ 980], 5.00th=[ 1032], 10.00th=[ 1080], 20.00th=[ 1160],
     | 30.00th=[ 1384], 40.00th=[ 1960], 50.00th=[ 3600], 60.00th=[ 7136],
     | 70.00th=[12352], 80.00th=[19840], 90.00th=[33024], 95.00th=[48896],
     | 99.00th=[94720], 99.50th=[118272], 99.90th=[214016], 99.95th=[292864],
     | 99.99th=[593920]
    bw (KB/s) : min= 12, max= 1615, per=6.34%, avg=560.66, stdev=208.24
    lat (usec) : 500=4.74%, 750=3.62%, 1000=2.43%
    lat (msec) : 2=20.69%, 4=8.44%, 10=18.48%, 20=18.77%, 50=17.43%
    lat (msec) : 100=4.47%, 250=0.84%, 500=0.08%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%
  cpu : usr=0.05%, sys=0.18%, ctx=200489, majf=0, minf=425
  IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued : total=r=99630/w=99512/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
   READ: io=1556.8MB, aggrb=8854KB/s, minb=8854KB/s, maxb=8854KB/s, mint=180028msec, maxt=180028msec
  WRITE: io=1554.9MB, aggrb=8844KB/s, minb=8844KB/s, maxb=8844KB/s, mint=180028msec, maxt=180028msec

Disk stats (read/write):
    md0: ios=99623/99537, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=24907/24886, aggrmerge=0/0, aggrticks=409488/310160, aggrin_queue=719646, aggrutil=83.27%
  xvdg: ios=22981/23053, merge=0/0, ticks=258421/160461, in_queue=418879, util=65.84%
  xvdh: ios=22914/22916, merge=0/0, ticks=504287/363848, in_queue=868131, util=83.27%
  xvdi: ios=30244/30190, merge=0/0, ticks=417784/236552, in_queue=654331, util=75.43%
  xvdf: ios=23491/23387, merge=0/0, ticks=457463/479781, in_queue=937243, util=83.03%

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3169