Re: Monitoring large resultsets

[Jerome Benezech]

There are quite a lot of slow queries and I know it comes down to index and code optimization. I'm doing them 1 by 1 but this app is using a lot of joomla extensions, some very poorly written so it takes time.

Anyway, for example, slow log:

Count: 7 Time=7.29s (51s) Lock=0.00s (0s) Rows=1586.6 (11106),

# Query_time: 11 Lock_time: 0 Rows_sent: 1 Rows_examined: 38800

SELECT COUNT(id) FROM jos_content, jos_ijoomla_archive_section_manager sm, jos_ijoomla_archive_categories_manager cm where ( created like '%2012-07-04%' and publish_up >= '2012-07-04' ) AND ( `sectionid`<>'0' ) AND ( `state`='1' OR `state`='-1' ) and sm.sec_show_archive='1' and ((sm.sec_id=jos_content.sectionid and jos_content.catid=cm.cat_id and cm.cat_show_archive='1') OR (jos_content.sectionid=0 and jos_content.catid=0));

mysqldump:
Count: 14 Time=8.00s (112s) Lock=0.00s (0s) Rows=1.0 (14),

SELECT COUNT(id) FROM jos_content, jos_ijoomla_archive_section_manager sm, jos_ijoomla_archive_categories_manager cm where ( created >='S' AND created<='S' AND UNIX_TIMESTAMP(publish_up)<=UNIX_TIMESTAMP(NOW()) ) AND ( `sectionid`<>'S' ) AND ( `state`='S' OR `state`='S' ) and sm.sec_show_archive='S' and ((sm.sec_id=jos_content.sectionid and jos_content.catid=cm.cat_id and cm.cat_show_archive='S') OR (jos_content.sectionid=N and jos_content.catid=N))

explain:

+----+-------------+-------------+-------+---------------------------------+-----------+---------+------+-------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+-------------+-------+---------------------------------+-----------+---------+------+-------+-------------+
| 1 | SIMPLE | jos_content | range | idx_section,idx_state,idx_catid | idx_state | 1 | NULL | 38791 | Using where |
| 1 | SIMPLE | sm | ALL | idx_secid,idx_secshowarchive | NULL | NULL | NULL | 10 | Using where |
| 1 | SIMPLE | cm | ALL | idx_catid,idx_catshowarchive | NULL | NULL | NULL | 81 | Using where |
+----+-------------+-------------+-------+---------------------------------+-----------+---------+------+-------+-------------+
3 rows in set, 1 warning (0.02 sec)



Create table for the main table:

 jos_content | CREATE TABLE `jos_content` (
  `id` int(11) unsigned NOT NULL auto_increment,
  `title` varchar(255) NOT NULL default '',
  `alias` varchar(255) NOT NULL default '',
  `title_alias` varchar(255) NOT NULL default '',
  `introtext` mediumtext NOT NULL,
  `fulltext` mediumtext NOT NULL,
  `state` tinyint(3) NOT NULL default '0',
  `sectionid` int(11) unsigned NOT NULL default '0',
  `mask` int(11) unsigned NOT NULL default '0',
  `catid` int(11) unsigned NOT NULL default '0',
  `created` datetime NOT NULL default '0000-00-00 00:00:00',
  `created_by` int(11) unsigned NOT NULL default '0',
  `created_by_alias` varchar(255) NOT NULL default '',
  `modified` datetime NOT NULL default '0000-00-00 00:00:00',
  `modified_by` int(11) unsigned NOT NULL default '0',
  `checked_out` int(11) unsigned NOT NULL default '0',
  `checked_out_time` datetime NOT NULL default '0000-00-00 00:00:00',
  `publish_up` datetime NOT NULL default '0000-00-00 00:00:00',
  `publish_down` datetime NOT NULL default '0000-00-00 00:00:00',
  `images` text NOT NULL,
  `urls` text NOT NULL,
  `attribs` text NOT NULL,
  `version` int(11) unsigned NOT NULL default '1',
  `parentid` int(11) unsigned NOT NULL default '0',
  `ordering` int(11) NOT NULL default '0',
  `metakey` text NOT NULL,
  `metadesc` text NOT NULL,
  `access` int(11) unsigned NOT NULL default '0',
  `hits` int(11) unsigned NOT NULL default '0',
  `metadata` text NOT NULL,
  PRIMARY KEY  (`id`),
  KEY `idx_section` (`sectionid`),
  KEY `idx_access` (`access`),
  KEY `idx_checkout` (`checked_out`),
  KEY `idx_state` (`state`),
  KEY `idx_catid` (`catid`),
  KEY `idx_createdby` (`created_by`)
) ENGINE=MyISAM AUTO_INCREMENT=81954 DEFAULT CHARSET=utf8

I know the query cannot use indexes properly and code needs to be changed.


I am also trying to look into queries with logs like this:
# Query_time: 5 Lock_time: 0 Rows_sent: 1674 Rows_examined: 14724
dump:
Count: 7 Time=7.29s (51s) Lock=0.00s (0s) Rows=1586.6 (11106)

Because I think they are returning too much data. In this example (the site is a news website), I think the query is returning the full content of articles displayed as latests news summaries on the front page.

Variables:

+-----------------------------------------+------------------------------------------+
| Variable_name | Value |
+-----------------------------------------+------------------------------------------+
| auto_increment_increment | 1 |
| auto_increment_offset | 1 |
| automatic_sp_privileges | ON |
| back_log | 50 |
| basedir | / |
| binlog_cache_size | 32768 |
| bulk_insert_buffer_size | 8388608 |
| character_set_client | utf8 |
| character_set_connection | utf8 |
| character_set_database | utf8 |
| character_set_filesystem | binary |
| character_set_results | utf8 |
| character_set_server | utf8 |
| character_set_system | utf8 |
| character_sets_dir | /usr/share/mysql/charsets/ |
| collation_connection | utf8_general_ci |
| collation_database | utf8_general_ci |
| collation_server | utf8_general_ci |
| completion_type | 0 |
| concurrent_insert | 1 |
| connect_timeout | 100 |
| datadir | /var/lib/mysql/ |
| date_format | %Y-%m-%d |
| datetime_format | %Y-%m-%d %H:%i:%s |
| default_week_format | 0 |
| delay_key_write | ON |
| delayed_insert_limit | 100 |
| delayed_insert_timeout | 100 |
| delayed_queue_size | 1000 |
| div_precision_increment | 4 |
| keep_files_on_create | OFF |
| engine_condition_pushdown | OFF |
| expire_logs_days | 0 |
| flush | OFF |
| flush_time | 0 |
| ft_boolean_syntax | + -><()~*:""&| |
| ft_max_word_len | 84 |
| ft_min_word_len | 3 |
| ft_query_expansion_limit | 20 |
| ft_stopword_file | (built-in) |
| group_concat_max_len | 1024 |
| have_archive | YES |
| have_bdb | NO |
| have_blackhole_engine | YES |
| have_compress | YES |
| have_community_features | NO |
| have_profiling | NO |
| have_crypt | YES |
| have_csv | YES |
| have_dynamic_loading | YES |
| have_example_engine | YES |
| have_federated_engine | YES |
| have_geometry | YES |
| have_innodb | YES |
| have_isam | NO |
| have_merge_engine | YES |
| have_ndbcluster | NO |
| have_openssl | NO |
| have_ssl | NO |
| have_query_cache | YES |
| have_raid | NO |
| have_rtree_keys | YES |
| have_symlink | YES |
| hostname | xxxxxxxxxx |
| init_connect | |
| init_file | |
| init_slave | |
| innodb_additional_mem_pool_size | 1048576 |
| innodb_autoextend_increment | 8 |
| innodb_buffer_pool_awe_mem_mb | 0 |
| innodb_buffer_pool_size | 8388608 |
| innodb_checksums | ON |
| innodb_commit_concurrency | 0 |
| innodb_concurrency_tickets | 500 |
| innodb_data_file_path | ibdata1:10M:autoextend |
| innodb_data_home_dir | |
| innodb_adaptive_hash_index | ON |
| innodb_doublewrite | ON |
| innodb_fast_shutdown | 1 |
| innodb_file_io_threads | 4 |
| innodb_file_per_table | ON |
| innodb_flush_log_at_trx_commit | 1 |
| innodb_flush_method | |
| innodb_force_recovery | 0 |
| innodb_lock_wait_timeout | 50 |
| innodb_locks_unsafe_for_binlog | OFF |
| innodb_log_arch_dir | |
| innodb_log_archive | OFF |
| innodb_log_buffer_size | 1048576 |
| innodb_log_file_size | 5242880 |
| innodb_log_files_in_group | 2 |
| innodb_log_group_home_dir | ./ |
| innodb_max_dirty_pages_pct | 90 |
| innodb_max_purge_lag | 0 |
| innodb_mirrored_log_groups | 1 |
| innodb_open_files | 300 |
| innodb_rollback_on_timeout | OFF |
| innodb_support_xa | ON |
| innodb_sync_spin_loops | 20 |
| innodb_table_locks | ON |
| innodb_thread_concurrency | 8 |
| innodb_thread_sleep_delay | 10000 |
| innodb_use_legacy_cardinality_algorithm | ON |
| interactive_timeout | 30 |
| join_buffer_size | 2097152 |
| key_buffer_size | 134217728 |
| key_cache_age_threshold | 300 |
| key_cache_block_size | 1024 |
| key_cache_division_limit | 100 |
| language | /usr/share/mysql/english/ |
| large_files_support | ON |
| large_page_size | 0 |
| large_pages | OFF |
| lc_time_names | en_US |
| license | GPL |
| local_infile | ON |
| locked_in_memory | OFF |
| log | OFF |
| log_bin | OFF |
| log_bin_trust_function_creators | OFF |
| log_error | /var/lib/mysql/mysql.err |
| log_queries_not_using_indexes | OFF |
| log_slave_updates | OFF |
| log_slow_queries | ON |
| log_warnings | 1 |
| long_query_time | 4 |
| low_priority_updates | OFF |
| lower_case_file_system | OFF |
| lower_case_table_names | 0 |
| max_allowed_packet | 8388608 |
| max_binlog_cache_size | 4294963200 |
| max_binlog_size | 1073741824 |
| max_connect_errors | 25 |
| max_connections | 150 |
| max_delayed_threads | 20 |
| max_error_count | 64 |
| max_heap_table_size | 268435456 |
| max_insert_delayed_threads | 20 |
| max_join_size | 18446744073709551615 |
| max_length_for_sort_data | 1024 |
| max_prepared_stmt_count | 16382 |
| max_relay_log_size | 0 |
| max_seeks_for_key | 4294967295 |
| max_sort_length | 1024 |
| max_sp_recursion_depth | 0 |
| max_tmp_tables | 10 |
| max_user_connections | 0 |
| max_write_lock_count | 4294967295 |
| multi_range_count | 256 |
| myisam_data_pointer_size | 6 |
| myisam_max_sort_file_size | 2146435072 |
| myisam_mmap_size | 4294967295 |
| myisam_recover_options | OFF |
| myisam_repair_threads | 1 |
| myisam_sort_buffer_size | 1048576 |
| myisam_stats_method | nulls_unequal |
| net_buffer_length | 16384 |
| net_read_timeout | 30 |
| net_retry_count | 10 |
| net_write_timeout | 60 |
| new | OFF |
| old_passwords | ON |
| open_files_limit | 50000 |
| optimizer_prune_level | 1 |
| optimizer_search_depth | 62 |
| pid_file | /var/lib/mysql/xxxxxxxx.pid |
| plugin_dir | |
| port | 3306 |
| preload_buffer_size | 32768 |
| protocol_version | 10 |
| query_alloc_block_size | 8192 |
| query_cache_limit | 536870912 |
| query_cache_min_res_unit | 4096 |
| query_cache_size | 2147483648 |
| query_cache_type | ON |
| query_cache_wlock_invalidate | OFF |
| query_prealloc_size | 8192 |
| range_alloc_block_size | 4096 |
| read_buffer_size | 1048576 |
| read_only | OFF |
| read_rnd_buffer_size | 2097152 |
| relay_log | |
| relay_log_index | |
| relay_log_info_file | relay-log.info |
| relay_log_purge | ON |
| relay_log_space_limit | 0 |
| rpl_recovery_rank | 0 |
| secure_auth | OFF |
| secure_file_priv | |
| server_id | 0 |
| skip_external_locking | ON |
| skip_networking | OFF |
| skip_show_database | OFF |
| slave_compressed_protocol | OFF |
| slave_load_tmpdir | /tmp_mysql/ |
| slave_net_timeout | 3600 |
| slave_skip_errors | OFF |
| slave_transaction_retries | 10 |
| slow_launch_time | 2 |
| socket | /var/lib/mysql/mysql.sock |
| sort_buffer_size | 2097152 |
| sql_big_selects | ON |
| sql_mode | |
| sql_notes | ON |
| sql_warnings | OFF |
| ssl_ca | |
| ssl_capath | |
| ssl_cert | |
| ssl_cipher | |
| ssl_key | |
| storage_engine | MyISAM |
| sync_binlog | 0 |
| sync_frm | ON |
| system_time_zone | ICT |
| table_cache | 4096 |
| table_lock_wait_timeout | 50 |
| table_type | MyISAM |
| thread_cache_size | 50 |
| thread_stack | 196608 |
| time_format | %H:%i:%s |
| time_zone | SYSTEM |
| timed_mutexes | OFF |
| tmp_table_size | 268435456 |
| tmpdir | /tmp_mysql |
| transaction_alloc_block_size | 8192 |
| transaction_prealloc_size | 4096 |
| tx_isolation | REPEATABLE-READ |
| updatable_views_with_limit | YES |
| version | 5.0.91-community-log |
| version_comment | MySQL Community Edition (GPL) |
| version_compile_machine | i686 |
| version_compile_os | pc-linux-gnu |
| wait_timeout | 30 |
+-----------------------------------------+------------------------------------------+


Status:


+-----------------------------------+------------+
| Variable_name | Value |
+-----------------------------------+------------+
| Aborted_clients | 1638 |
| Aborted_connects | 547 |
| Binlog_cache_disk_use | 0 |
| Binlog_cache_use | 0 |
| Bytes_received | 108989142 |
| Bytes_sent | 2072944949 |
| Com_admin_commands | 1 |
| Com_alter_db | 0 |
| Com_alter_table | 0 |
| Com_analyze | 0 |
| Com_backup_table | 0 |
| Com_begin | 0 |
| Com_call_procedure | 0 |
| Com_change_db | 34183 |
| Com_change_master | 0 |
| Com_check | 0 |
| Com_checksum | 0 |
| Com_commit | 0 |
| Com_create_db | 0 |
| Com_create_function | 0 |
| Com_create_index | 0 |
| Com_create_table | 0 |
| Com_create_user | 0 |
| Com_dealloc_sql | 0 |
| Com_delete | 6049 |
| Com_delete_multi | 0 |
| Com_do | 0 |
| Com_drop_db | 0 |
| Com_drop_function | 0 |
| Com_drop_index | 0 |
| Com_drop_table | 0 |
| Com_drop_user | 0 |
| Com_execute_sql | 0 |
| Com_flush | 1 |
| Com_grant | 13 |
| Com_ha_close | 0 |
| Com_ha_open | 0 |
| Com_ha_read | 0 |
| Com_help | 0 |
| Com_insert | 5505 |
| Com_insert_select | 1 |
| Com_kill | 0 |
| Com_load | 0 |
| Com_load_master_data | 0 |
| Com_load_master_table | 0 |
| Com_lock_tables | 0 |
| Com_optimize | 0 |
| Com_preload_keys | 0 |
| Com_prepare_sql | 0 |
| Com_purge | 0 |
| Com_purge_before_date | 0 |
| Com_rename_table | 0 |
| Com_repair | 0 |
| Com_replace | 23 |
| Com_replace_select | 0 |
| Com_reset | 0 |
| Com_restore_table | 0 |
| Com_revoke | 0 |
| Com_revoke_all | 0 |
| Com_rollback | 0 |
| Com_savepoint | 0 |
| Com_select | 195924 |
| Com_set_option | 68410 |
| Com_show_binlog_events | 0 |
| Com_show_binlogs | 1 |
| Com_show_charsets | 1 |
| Com_show_collations | 1 |
| Com_show_column_types | 0 |
| Com_show_create_db | 0 |
| Com_show_create_table | 2 |
| Com_show_databases | 12 |
| Com_show_errors | 0 |
| Com_show_fields | 1402 |
| Com_show_grants | 1 |
| Com_show_innodb_status | 0 |
| Com_show_keys | 4 |
| Com_show_logs | 0 |
| Com_show_master_status | 2 |
| Com_show_ndb_status | 0 |
| Com_show_new_master | 0 |
| Com_show_open_tables | 0 |
| Com_show_privileges | 0 |
| Com_show_processlist | 58 |
| Com_show_slave_hosts | 0 |
| Com_show_slave_status | 2 |
| Com_show_status | 141 |
| Com_show_storage_engines | 0 |
| Com_show_tables | 67 |
| Com_show_triggers | 0 |
| Com_show_variables | 10 |
| Com_show_warnings | 0 |
| Com_slave_start | 0 |
| Com_slave_stop | 0 |
| Com_stmt_close | 0 |
| Com_stmt_execute | 0 |
| Com_stmt_fetch | 0 |
| Com_stmt_prepare | 0 |
| Com_stmt_reset | 0 |
| Com_stmt_send_long_data | 0 |
| Com_truncate | 0 |
| Com_unlock_tables | 0 |
| Com_update | 25211 |
| Com_update_multi | 0 |
| 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 | 34877 |
| Created_tmp_disk_tables | 12342 |
| Created_tmp_files | 60 |
| Created_tmp_tables | 13086 |
| Delayed_errors | 0 |
| Delayed_insert_threads | 0 |
| Delayed_writes | 0 |
| Flush_commands | 1 |
| Handler_commit | 3 |
| Handler_delete | 401360 |
| Handler_discover | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 6222 |
| Handler_read_key | 16175087 |
| Handler_read_next | 86872306 |
| Handler_read_prev | 614 |
| Handler_read_rnd | 2421321 |
| Handler_read_rnd_next | 29454276 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 3073971 |
| Handler_write | 3394086 |
| Innodb_buffer_pool_pages_data | 70 |
| Innodb_buffer_pool_pages_dirty | 0 |
| Innodb_buffer_pool_pages_flushed | 10 |
| Innodb_buffer_pool_pages_free | 441 |
| Innodb_buffer_pool_pages_misc | 1 |
| Innodb_buffer_pool_pages_total | 512 |
| Innodb_buffer_pool_read_ahead_rnd | 2 |
| Innodb_buffer_pool_read_ahead_seq | 0 |
| Innodb_buffer_pool_read_requests | 3145 |
| Innodb_buffer_pool_reads | 60 |
| Innodb_buffer_pool_wait_free | 0 |
| Innodb_buffer_pool_write_requests | 16 |
| Innodb_data_fsyncs | 23 |
| Innodb_data_pending_fsyncs | 0 |
| Innodb_data_pending_reads | 0 |
| Innodb_data_pending_writes | 0 |
| Innodb_data_read | 3330048 |
| Innodb_data_reads | 86 |
| Innodb_data_writes | 25 |
| Innodb_data_written | 333824 |
| Innodb_dblwr_pages_written | 10 |
| Innodb_dblwr_writes | 4 |
| Innodb_log_waits | 0 |
| Innodb_log_write_requests | 1 |
| Innodb_log_writes | 5 |
| Innodb_os_log_fsyncs | 11 |
| Innodb_os_log_pending_fsyncs | 0 |
| Innodb_os_log_pending_writes | 0 |
| Innodb_os_log_written | 3072 |
| Innodb_page_size | 16384 |
| Innodb_pages_created | 0 |
| Innodb_pages_read | 70 |
| Innodb_pages_written | 10 |
| Innodb_row_lock_current_waits | 0 |
| Innodb_row_lock_time | 0 |
| Innodb_row_lock_time_avg | 0 |
| Innodb_row_lock_time_max | 0 |
| Innodb_row_lock_waits | 0 |
| Innodb_rows_deleted | 0 |
| Innodb_rows_inserted | 0 |
| Innodb_rows_read | 1168 |
| Innodb_rows_updated | 3 |
| Key_blocks_not_flushed | 0 |
| Key_blocks_unused | 96046 |
| Key_blocks_used | 19935 |
| Key_read_requests | 36880649 |
| Key_reads | 19881 |
| Key_write_requests | 1065534 |
| Key_writes | 46201 |
| Last_query_cost | 0.000000 |
| Max_used_connections | 151 |
| Not_flushed_delayed_rows | 0 |
| Open_files | 1413 |
| Open_streams | 0 |
| Open_tables | 862 |
| Opened_tables | 868 |
| Prepared_stmt_count | 0 |
| Qcache_free_blocks | 524 |
| Qcache_free_memory | 360547704 |
| Qcache_hits | 405394 |
| Qcache_inserts | 174847 |
| Qcache_lowmem_prunes | 2776 |
| Qcache_not_cached | 21300 |
| Qcache_queries_in_cache | 8248 |
| Qcache_total_blocks | 23154 |
| Queries | 774986 |
| Questions | 774986 |
| Rpl_status | NULL |
| Select_full_join | 1827 |
| Select_full_range_join | 6 |
| Select_range | 5826 |
| Select_range_check | 0 |
| Select_scan | 18612 |
| Slave_open_temp_tables | 0 |
| Slave_retried_transactions | 0 |
| Slave_running | OFF |
| Slow_launch_threads | 0 |
| Slow_queries | 80 |
| Sort_merge_passes | 54 |
| Sort_range | 21787 |
| Sort_rows | 8170020 |
| Sort_scan | 13326 |
| Table_locks_immediate | 344690 |
| Table_locks_waited | 2608 |
| Tc_log_max_pages_used | 0 |
| Tc_log_page_size | 0 |
| Tc_log_page_waits | 0 |
| Threads_cached | 28 |
| Threads_connected | 22 |
| Threads_created | 438 |
| Threads_running | 1 |
| Uptime | 2805 |
+-----------------------------------+------------+
Uptime: 2805 Threads: 22 Questions: 774987 Slow queries: 80 Opens: 868 Flush tables: 1 Open tables: 862 Queries per second avg: 276.288