Profiling/Live 20040715 1038
Appearance
This run was with the rebuild search index script running. On Ariel as master. Ran for about 5 minutes. This was to obtain data prior to turning off the query cache on Ariel MySQL. A run after that change is at Profiling/Live 20040715 1110. This script modified to make the columns line up neatly.
sql enwiki -vvv <~jamesday/profiling.sql -------------- select @total:=pf_time from profiling where pf_name='-total' -------------- +-----------------+ | @total:=pf_time | +-----------------+ | 47993.03125 | +-----------------+ 1 row in set (0.00 sec) -------------- select left(pf_name,70) as name, pf_time as total, pf_count as count, truncate(pf_time/pf_count,8) as each, truncate(pf_time/@total*100,8) as percent from profiling order by pf_time desc -------------- +------------------------------------------------------------------------+----------+-------+---------------+--------------+ | name | total | count | each | percent | +------------------------------------------------------------------------+----------+-------+---------------+--------------+ | -total | 47993 | 84 | 571.34561011 | 100.00000000 | | Article::view | 10704.6 | 53 | 201.97438826 | 22.30457693 | | Setup.php | 8865.71 | 82 | 108.11846179 | 18.47291916 | | Parser::parse | 8801.88 | 37 | 237.88859269 | 18.33990831 | | OutputPage::output | 8369.28 | 84 | 99.63425409 | 17.43852623 | | query: SELECT cur_id,cur_namespace,cur_title,cur_text FROM cur,searchi | 8350.12 | 5 | 1670.02421875 | 17.39861158 | | Parser::internalParse | 7804.28 | 53 | 147.25061726 | 16.26128317 | | Setup.php-MessageCache | 5531.39 | 84 | 65.84992327 | 11.52540985 | | query: COMMIT | 5447.83 | 114 | 47.78796600 | 11.35128993 | | Parser::replaceInternalLinks | 4378.63 | 114 | 38.40905975 | 9.12347625 | | LinkCache::addLinkObj | 3489.35 | 571 | 6.11093775 | 7.27052525 | | query: SELECT cur_id FROM cur WHERE cur_namespace=N AND cur_title='X' | 3266.12 | 547 | 5.97097002 | 6.80540595 | | Parser::replaceVariables | 3200 | 354 | 9.03955216 | 6.66763774 | | wfMsg | 2772.63 | 4019 | 0.68988078 | 5.77715303 | | Setup.php-misc | 2023.54 | 83 | 24.38002253 | 4.21632436 | | query: SELECT cur_id,cur_namespace,cur_title,cur_text FROM cur,searchi | 1703.93 | 10 | 170.39315185 | 3.55037278 | | -overhead-total | 1484.44 | 20559 | 0.07220412 | 3.09304218 | | ParserCache::get | 1470.18 | 52 | 28.27270273 | 3.06332086 | | Title::secureAndSplit | 1297.41 | 4644 | 0.27937391 | 2.70333513 | | main-misc-setup | 1263.1 | 84 | 15.03691319 | 2.63184190 | | query: SHOW COLUMNS FROM cur LIKE 'X'; | 1161.35 | 78 | 14.88908660 | 2.41982788 | | Parser::tidy | 1152.16 | 37 | 31.13942739 | 2.40067939 | | Title::newFromText | 905.262 | 3806 | 0.23785122 | 1.88623588 | | query: SELECT ss_total_views, ss_total_edits, ss_good_articles FROM si | 876.192 | 71 | 12.34073004 | 1.82566470 | | -overhead-internal | 842.366 | 20559 | 0.04097311 | 1.75518468 | | Parser::replaceExternalLinks | 735.351 | 57 | 12.90089389 | 1.53220359 | | Setup.php-includes | 658.548 | 84 | 7.83986118 | 1.37217492 | | query: BEGIN | 558.178 | 112 | 4.98372868 | 1.16303887 | | Skin::makeKnownLinkObj | 528.768 | 1855 | 0.28505036 | 1.10176085 | | Article::getContent | 516.917 | 38 | 13.60308356 | 1.07706715 | | LinkCache::preFill | 476.815 | 32 | 14.90047264 | 0.99350908 | | query: SELECT cur_text,cur_timestamp,cur_user,cur_user_text,cur_commen | 473.867 | 36 | 13.16298421 | 0.98736716 | | Parser::doBlockLevels | 456.13 | 37 | 12.32782724 | 0.95040799 | | query: SELECT lcc_cacheobj FROM linkscc WHERE lcc_pageid = N | 433.259 | 31 | 13.97609686 | 0.90275398 | | query: SELECT cur_text FROM cur WHERE cur_namespace=N AND cur_title='X | 287.47 | 88 | 3.26670594 | 0.59898305 | | query: SELECT N FROM user_newtalk WHERE user_ip='X' | 246.018 | 75 | 3.28023579 | 0.51261126 | | Skin::outputPage | 228.446 | 2 | 114.22281646 | 0.47599750 | | Setup.php-language | 222.716 | 83 | 2.68332184 | 0.46405844 | | Skin::doAfterContent | 177.893 | 2 | 88.94638824 | 0.37066376 | | query: UPDATE cur SET cur_text='X' | 165.582 | 1 | 165.58206176 | 0.34501271 | | query: SELECT cur_id,cur_namespace,cur_title,cur_is_redirect FROM link | 163.063 | 1 | 163.06336975 | 0.33976468 | | Setup.php-User | 155.17 | 84 | 1.84725770 | 0.32331703 | | query: SELECT cur_user,cur_user_text,cur_timestamp,cur_comment,cur_min | 141.044 | 30 | 4.70147654 | 0.29388495 | | Skin::doAfterContent-3 | 133.261 | 2 | 66.63040924 | 0.27766701 | | query: SELECT cur_restrictions FROM cur WHERE (cur_id=N) | 126.423 | 27 | 4.68233235 | 0.26341943 | | query: SELECT N FROM watchlist WHERE wl_user=N AND wl_namespace=N AND | 99.9756 | 9 | 11.10839758 | 0.20831269 | | Setup.php-SetupSession | 98.6609 | 84 | 1.17453466 | 0.20557341 | | Parser::removeHTMLtags | 82.2069 | 53 | 1.55107289 | 0.17128916 | | Skin::makeLink | 80.4976 | 15 | 5.36650492 | 0.16772762 | | Parser::doAllQuotes | 77.8258 | 57 | 1.36536568 | 0.16216071 | | Setup.php-OutputPage | 65.721 | 84 | 0.78239268 | 0.13693860 | | query: SELECT cur_touched,cur_is_redirect FROM cur WHERE cur_id=N | 60.6222 | 23 | 2.63574649 | 0.12631452 | | query: SELECT cur_text,cur_timestamp,cur_user,cur_counter,cur_restrict | 60.1137 | 14 | 4.29383713 | 0.12525510 | | Setup.php-DateFormatter | 48.1026 | 84 | 0.57264977 | 0.10022826 | | Skin::doAfterContent-4 | 44.057 | 2 | 22.02849578 | 0.09179872 | | Skin::quickBar | 43.9137 | 2 | 21.95685005 | 0.09150015 | | Skin::doBeforeContent | 40.0239 | 2 | 20.01195144 | 0.08339523 | | Skin::makeBrokenLinkObj | 39.3521 | 88 | 0.44718352 | 0.08199555 | | Setup.php-memcached | 37.2774 | 84 | 0.44377867 | 0.07767254 | | Setup.php-extensions | 36.6542 | 82 | 0.44700245 | 0.07637400 | | query: SELECT user_name,user_password,user_newpassword,user_email,user | 31.0269 | 2 | 15.51342582 | 0.06464866 | | query: SELECT cur_id,cur_namespace,cur_title,cur_user,cur_comment,cur_ | 28.4252 | 1 | 28.42518997 | 0.05922774 | | Parser::doHeadings | 21.8692 | 57 | 0.38367063 | 0.04556750 | | query: SELECT cur_id,cur_namespace,cur_title FROM cur,links WHERE cur_ | 12.5253 | 2 | 6.26265716 | 0.02609819 | | Setup.php-database | 10.9261 | 83 | 0.13163973 | 0.02276600 | | query: SELECT * FROM ipblocks WHERE ipb_user=N | 10.1019 | 8 | 1.26273894 | 0.02104870 | | query: SELECT bl_to FROM brokenlinks WHERE bl_from='X' | 9.11021 | 2 | 4.55510330 | 0.01898235 | | Skin::initPage | 9.06124 | 70 | 0.12944635 | 0.01888033 | | Parser::replaceInternalLinks-setup | 8.85656 | 106 | 0.08355245 | 0.01845384 | | query: SELECT N FROM user_newtalk WHERE user_id=N | 8.04497 | 2 | 4.02248477 | 0.01676278 | | query: SELECT oi_size AS img_size, oi_description AS img_description,o | 6.31876 | 4 | 1.57968974 | 0.01316599 | | query: SELECT DISTINCT 'X' as type, N as namespace, cl_to as title, N | 6.17373 | 1 | 6.17372608 | 0.01286379 | | query: SELECT img_size,img_description,img_user,img_user_text,img_time | 4.58569 | 4 | 1.14642357 | 0.00955491 | | query: SELECT cur_namespace,cur_title FROM imagelinks,cur WHERE il_to= | 3.97177 | 4 | 0.99294161 | 0.00827571 | | PageHistory::history | 3.94328 | 1 | 3.94327974 | 0.00821635 | | query: SELECT * FROM ipblocks WHERE (ipb_address='X' OR ipb_user=N) | 2.10189 | 2 | 1.05094683 | 0.00437958 | | query: SELECT iw_url,iw_local FROM interwiki WHERE iw_prefix='X' | 0.656245 | 1 | 0.65624547 | 0.00136737 | | query: REPLACE INTO linkscc(lcc_pageid,lcc_cacheobj) VALUES(N, 'X') | 0.654215 | 2 | 0.32710757 | 0.00136314 | | Setup.php-BlockCache | 0.58583 | 83 | 0.00705819 | 0.00122065 | | query: SELECT cur_id,cur_title FROM cur USE INDEX (cur_random) WHERE c | 0.553146 | 1 | 0.55314552 | 0.00115255 | | query: INSERT INTO old (old_namespace,old_title,old_text,old_comment,o | 0.510091 | 1 | 0.51009058 | 0.00106284 | | query: INSERT INTO recentchanges (rc_timestamp,rc_cur_time,rc_namespac | 0.377053 | 1 | 0.37705302 | 0.00078564 | | query: UPDATE recentchanges SET rc_this_oldid=N WHERE rc_namespace=N A | 0.341052 | 1 | 0.34105181 | 0.00071062 | | query: SELECT old_id,old_user,old_comment,old_user_text,old_timestamp, | 0.28117 | 1 | 0.28117039 | 0.00058585 | | query: UPDATE recentchanges SET rc_cur_time='X' WHERE rc_cur_id=N | 0.268096 | 1 | 0.26809573 | 0.00055861 | | query: DELETE FROM linkscc WHERE lcc_pageid='X' | 0.236148 | 1 | 0.23614764 | 0.00049204 | | Skin::doAfterContent-2 | 0.118829 | 2 | 0.05941462 | 0.00024759 | | Skin::doAfterContent-1 | 0.025846 | 2 | 0.01292300 | 0.00005385 | | Parser::replaceInternalLinks-prefixhandling | -3.10276 | 1388 | -0.00223541 | -0.00646501 | +------------------------------------------------------------------------+----------+-------+---------------+--------------+ 89 rows in set (0.00 sec)
MySQL configuration
[edit]Just after that run, the MySQL configuration and status was:
MySQL on localhost (4.0.20-log) up 3+21:20:21 [11:22:45] Queries: 306.4M qps: 956 Slow: 25.0k Se/In/Up/De(%): 73/00/00/00 qps now: 1023 Slow qps: 0.0 Threads: 56 ( 7/ 70) 78/01/01/00 Cache Hits: 42.0M Hits/s: 131.2 Hits now: 0.0 Ratio: 18.7% Ratio now: 0.0% Key Efficiency: 99.7% Bps in/out: 9.7k/ 3.5k Now in/out: 158.7k/740.0k mysql> show variables; +---------------------------------+------------------------------------------------------------------------------------------------------------------------------------------- | Variable_name | Value +---------------------------------+------------------------------------------------------------------------------------------------------------------------------------------- | back_log | 50 | basedir | /usr/local/mysql/ | binlog_cache_size | 32768 | bulk_insert_buffer_size | 8388608 | character_set | latin1 | character_sets | latin1 dec8 dos german1 hp8 koi8_ru latin2 swe7 usa7 cp1251 danish hebrew win1251 estonia hungarian koi8_ukr win1251ukr greek win1250 croa cp1257 latin5 | | concurrent_insert | ON | connect_timeout | 5 | convert_character_set | | datadir | /usr/local/mysql/var/ | default_week_format | 0 | delay_key_write | ON | delayed_insert_limit | 100 | delayed_insert_timeout | 300 | delayed_queue_size | 1000 | flush | OFF | flush_time | 0 | ft_boolean_syntax | + -><()~*:""&| | ft_min_word_len | 2 | ft_max_word_len | 254 | ft_max_word_len_for_sort | 20 | ft_stopword_file | (built-in) | have_bdb | NO | have_crypt | YES | have_innodb | YES | have_isam | YES | have_raid | NO | have_symlink | YES | have_openssl | NO | have_query_cache | YES | init_file | | innodb_additional_mem_pool_size | 1048576 | innodb_buffer_pool_size | 1157627904 | innodb_data_file_path | /mnt/raid1/ibdata1:68000M;/usr/local/mysql/data/ibdata2:50M:autoextend | innodb_data_home_dir | | innodb_file_io_threads | 8 | innodb_force_recovery | 0 | innodb_thread_concurrency | 8 | innodb_flush_log_at_trx_commit | 1 | innodb_fast_shutdown | ON | innodb_flush_method | | innodb_lock_wait_timeout | 50 | innodb_log_arch_dir | ./ | innodb_log_archive | OFF | innodb_log_buffer_size | 8388608 | innodb_log_file_size | 83886080 | innodb_log_files_in_group | 2 | innodb_log_group_home_dir | ./ | innodb_mirrored_log_groups | 1 | innodb_max_dirty_pages_pct | 90 | interactive_timeout | 28800 | join_buffer_size | 256000000 | key_buffer_size | 402653184 | language | /usr/local/mysql/share/mysql/english/ | large_files_support | ON | license | GPL | local_infile | ON | locked_in_memory | OFF | log | OFF | log_update | OFF | log_bin | ON | log_slave_updates | OFF | log_slow_queries | OFF | log_warnings | ON | long_query_time | 10 | low_priority_updates | OFF | lower_case_file_system | OFF | lower_case_table_names | 0 | max_allowed_packet | 16776192 | max_binlog_cache_size | 536870912 | max_binlog_size | 1073741824 | max_connections | 600 | max_connect_errors | 40000 | max_delayed_threads | 20 | max_insert_delayed_threads | 20 | max_heap_table_size | 16777216 | max_join_size | 40048576000 | max_relay_log_size | 0 | max_seeks_for_key | 4294967295 | max_sort_length | 1024 | max_user_connections | 0 | max_tmp_tables | 32 | max_write_lock_count | 4294967295 | myisam_max_extra_sort_file_size | 268435456 | myisam_max_sort_file_size | 9223372036854775807 | myisam_repair_threads | 1 | myisam_recover_options | OFF | myisam_sort_buffer_size | 33554432 | net_buffer_length | 16384 | net_read_timeout | 30 | net_retry_count | 10 | net_write_timeout | 60 | new | OFF | open_files_limit | 8610 | pid_file | /usr/local/mysql/var/ariel.wikimedia.org.pid | log_error | | port | 3306 | protocol_version | 10 | query_alloc_block_size | 32768 | query_cache_limit | 4190208 | query_cache_size | 134216704 | query_cache_type | ON | query_prealloc_size | 32768 | range_alloc_block_size | 2048 | read_buffer_size | 4190208 | read_only | OFF | read_rnd_buffer_size | 4190208 | rpl_recovery_rank | 0 | server_id | 2 | slave_net_timeout | 3600 | skip_external_locking | ON | skip_networking | OFF | skip_show_database | OFF | slow_launch_time | 2 | socket | /tmp/mysql.sock | sort_buffer_size | 134217720 | sql_mode | 0 | table_cache | 4000 | table_type | MYISAM | thread_cache_size | 90 | thread_stack | 196608 | tx_isolation | REPEATABLE-READ | timezone | UTC | tmp_table_size | 268435456 | tmpdir | /tmp/ | transaction_alloc_block_size | 8192 | transaction_prealloc_size | 4096 | version | 4.0.20-log | version_comment | Source distribution | version_compile_os | unknown-linux | wait_timeout | 28800 131 rows in set (0.04 sec) mysql> show status -> ; +--------------------------+------------+ | Variable_name | Value | +--------------------------+------------+ | Aborted_clients | 4035 | | Aborted_connects | 1474 | | Bytes_received | 3244757622 | 9698 /s | Bytes_sent | 641451089 | 1915 /s | Com_admin_commands | 220 | | Com_alter_table | 0 | | Com_analyze | 0 | | Com_backup_table | 0 | | Com_begin | 20107946 | 60 /s | Com_change_db | 14732198 | 44 /s | Com_change_master | 0 | | Com_check | 0 | | Com_commit | 18269100 | 54.5 /s | Com_create_db | 0 | | Com_create_function | 0 | | Com_create_index | 0 | | Com_create_table | 0 | | Com_delete | 892719 | 2.66 /s | Com_delete_multi | 49641 | | Com_drop_db | 0 | | Com_drop_function | 0 | | Com_drop_index | 0 | | Com_drop_table | 0 | | Com_flush | 0 | | Com_grant | 1 | | Com_ha_close | 0 | | Com_ha_open | 0 | | Com_ha_read | 0 | | Com_insert | 850339 | 2.54 /s | Com_insert_select | 13696 | | Com_kill | 15 | | Com_load | 0 | | Com_load_master_data | 0 | | Com_load_master_table | 0 | | Com_lock_tables | 1675 | | Com_optimize | 0 | | Com_purge | 0 | | Com_rename_table | 0 | | Com_repair | 0 | | Com_replace | 415389 | 1.24 /s | Com_replace_select | 0 | | Com_reset | 0 | | Com_restore_table | 0 | | Com_revoke | 0 | | Com_rollback | 0 | | Com_savepoint | 0 | | Com_select | 190361948 | 568 /s | Com_set_option | 16 | | Com_show_binlog_events | 0 | | Com_show_binlogs | 0 | | Com_show_create | 0 | | Com_show_databases | 0 | | Com_show_fields | 14322096 | | Com_show_grants | 7 | | Com_show_keys | 0 | | Com_show_logs | 0 | | Com_show_master_status | 3 | | Com_show_new_master | 0 | | Com_show_open_tables | 0 | | Com_show_processlist | 67371 | | Com_show_slave_hosts | 4 | | Com_show_slave_status | 2792 | | Com_show_status | 67264 | | Com_show_innodb_status | 14 | | Com_show_tables | 0 | | Com_show_variables | 706 | | Com_slave_start | 0 | | Com_slave_stop | 1 | | Com_truncate | 4 | | Com_unlock_tables | 740 | 0.002/s | Com_update | 1409143 | 4.21 /s | Connections | 14736995 | 44 /s | Created_tmp_disk_tables | 168804 | 0.504/s | Created_tmp_tables | 289937 | 0.865/s | Created_tmp_files | 29595 | 0.088/s | Delayed_insert_threads | 0 | | Delayed_writes | 0 | | Delayed_errors | 0 | | Flush_commands | 1 | | Handler_commit | 18268479 | 54.5 /s | Handler_delete | 9978 | 0.030/s | Handler_read_first | 563551 | 1.68 /s | Handler_read_key | 785219845 | 2344 /s | Handler_read_next | 1647478254 | 4918 /s | Handler_read_prev | 3917 | 0.012/s | Handler_read_rnd | 53596699 | 160 /s | Handler_read_rnd_next | 773495351 | 2309 /s | Handler_rollback | 14617386 | 43.6 /s | Handler_update | 805558 | 2.4 /s | Handler_write | 462539104 | 1381 /s | Key_blocks_used | 360922 | | Key_read_requests | 2426876272 | 7244 /s (from cache) | Key_reads | 7630976 | 22.8 /s (not cached) | Key_write_requests | 21996779 | 65.7 /s (to cache) | Key_writes | 15561503 | 46.5 /s (not cached) | Max_used_connections | 600 | | Not_flushed_key_blocks | 5647 | | Not_flushed_delayed_rows | 0 | | Open_tables | 4000 | | Open_files | 487 | | Open_streams | 0 | | Opened_tables | 17776 | 0.05 /s | Questions | 320372613 | 956 /s | Qcache_queries_in_cache | 30888 | | Qcache_inserts | 46156168 | 138 /s | Qcache_hits | 44074242 | 132 /s | Qcache_lowmem_prunes | 386781 | | Qcache_not_cached | 144144607 | 430 /s | Qcache_free_memory | 87042096 | | Qcache_free_blocks | 23086 | | Qcache_total_blocks | 87002 | | Rpl_status | NULL | | Select_full_join | 319 | 0.00095/s | Select_full_range_join | 1 | | Select_range | 587224 | 1.75 /s | Select_range_check | 73595 | 0.22 /s | Select_scan | 566753 | 1.69 /s | Slave_open_temp_tables | 0 | | Slave_running | OFF | | Slow_launch_threads | 4 | | Slow_queries | 25544 | 0.076/s | Sort_merge_passes | 0 | | Sort_range | 226056 | 0.68 /s | Sort_rows | 345343535 | 1031 /s | Sort_scan | 285706 | 0.9 /s | Table_locks_immediate | 196142473 | 585 /s | Table_locks_waited | 16050 | 0.05 /s | Threads_cached | 70 | | Threads_created | 59791 | 0.2 /s | Threads_connected | 54 | | Threads_running | 6 | | Uptime | 335001 | +--------------------------+------------+ 132 rows in set (0.00 sec) mysql> show innodb status; ===================================== 040715 11:05:49 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 7 seconds ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 38474719, signal count 26877327 Mutex spin waits 5032302123, rounds 6879430350, OS waits 22078448 RW-shared spins 32299977, OS waits 8831142; RW-excl spins 105306949, OS waits 4697007 ------------------------ LATEST DETECTED DEADLOCK ------------------------ censored ------------ TRANSACTIONS ------------ Trx id counter 0 59259588 Purge done for trx's n:o < 0 14694830 undo n:o < 0 0 Total number of lock structs in row lock hash table 382 LIST OF TRANSACTIONS FOR EACH SESSION: censored -------- FILE I/O -------- I/O thread 0 state: waiting for i/o request (insert buffer thread) I/O thread 1 state: waiting for i/o request (log thread) I/O thread 2 state: waiting for i/o request (read thread) I/O thread 3 state: waiting for i/o request (write thread) Pending normal aio reads: 0, aio writes: 0, ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 22342829 OS file reads, 3488216 OS file writes, 1361198 OS fsyncs 2 pending preads, 0 pending pwrites 74.28 reads/s, 27065 avg bytes/read, 36.99 writes/s, 8.43 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf for space 0: size 408, free list len 211, seg size 620, 1447193 inserts, 1359726 merged recs, 571768 merges Hash table size 10791019, used cells 2531339, node heap has 4254 buffer(s) 13764.03 hash searches/s, 6894.59 non-hash searches/s --- LOG --- Log sequence number 18 3673184614 Log flushed up to 18 3673177671 Last checkpoint at 18 3555296151 0 pending log writes, 0 pending chkp writes 1201508 log i/o's done, 6.86 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 6031198976; in additional pool allocated 1048576 Buffer pool size 332800 Free buffers 0 Database pages 328544 Modified db pages 23012 Pending reads 1 Pending writes: LRU 0, flush list 0, single page 0 Pages read 30683803, created 481274, written 3318833 119.41 reads/s, 1.86 creates/s, 41.57 writes/s Buffer pool hit rate 999 / 1000 -------------- ROW OPERATIONS -------------- 1 queries inside InnoDB, 0 queries in queue Main thread process no. 13834, id 1132460384, state: sleeping Number of rows inserted 2602193, updated 3606888, deleted 1726610, read 32135195380 4.71 inserts/s, 3.29 updates/s, 1.57 deletes/s, 9436.51 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================