Database-driven pages very slow on first load; why? Apache+PHP

Question

One of our company's Apache/PHP/MySQL driven sites is being moved to a new server. It is not yet moved to production, so there are only two users or so. Still, loading a page using the database can take several seconds.

As an example: 13.8s at the first page load, and 0.01-0.02s on subsequent page loads. That's on a page with 30 queries.

I suppose some kind of MySQL cache is involved, but my main problem is: why is the initial load so enormously slow? Can anything be diagnosed from this? Especially, there are some large numbers in the MySQL SHOW STATUS output that worry me.

top output:

top - 12:22:33 up 163 days, 22:45, 7 users, load average: 0.09, 0.16, 0.29 Tasks: 960 total, 1 running, 959 sleeping, 0 stopped, 0 zombie Cpu(s): 0.3%us, 0.7%sy, 0.0%ni, 99.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 1025492k total, 700924k used, 324568k free, 21132k buffers Swap: 1044476k total, 538772k used, 505704k free, 114796k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 21571 anna 20 0 3356 1676 852 R 2 0.2 0:00.18 top 4903 anna 20 0 6176 1824 628 S 0 0.2 0:02.94 screen 1 root 20 0 3312 688 404 S 0 0.1 1:00.89 init 2 root 20 0 0 0 0 S 0 0.0 0:00.19 kthreadd 3 root 20 0 0 0 0 S 0 0.0 0:46.33 ksoftirqd/0 6 root RT 0 0 0 0 S 0 0.0 0:00.00 migration/0 7 root RT 0 0 0 0 S 0 0.0 0:00.00 migration/1 9 root 20 0 0 0 0 S 0 0.0 1:49.59 ksoftirqd/1 11 root 0 -20 0 0 0 S 0 0.0 0:00.00 cpuset 

MySQL SHOW STATUS

Variable_name Value Aborted_clients 1 Aborted_connects 19 Binlog_cache_disk_use 0 Binlog_cache_use 0 Bytes_received 128 Bytes_sent 163 Compression OFF Connections 160078 Created_tmp_disk_tables 0 Created_tmp_files 23 Created_tmp_tables 0 Delayed_errors 0 Delayed_insert_threads 0 Delayed_writes 0 Flush_commands 1 Innodb_buffer_pool_pages_data 505 Innodb_buffer_pool_pages_dirty 0 Innodb_buffer_pool_pages_flushed 1969738 Innodb_buffer_pool_pages_free 1 Innodb_buffer_pool_pages_misc 6 Innodb_buffer_pool_pages_total 512 Innodb_buffer_pool_read_ahead_rnd 27256 Innodb_buffer_pool_read_ahead_seq 59242 Innodb_buffer_pool_read_requests 3503466291 Innodb_buffer_pool_reads 325582 Innodb_buffer_pool_wait_free 0 Innodb_buffer_pool_write_requests 214340468 Innodb_data_fsyncs 521160 Innodb_data_pending_fsyncs 0 Innodb_data_pending_reads 0 Innodb_data_pending_writes 0 Innodb_data_read 1133531136 Innodb_data_reads 478093 Innodb_data_writes 1008163 Innodb_data_written 1610111488 Innodb_dblwr_pages_written 1969738 Innodb_dblwr_writes 103107 Innodb_log_waits 1 Innodb_log_write_requests 27797124 Innodb_log_writes 261768 Innodb_os_log_fsyncs 314984 Innodb_os_log_pending_fsyncs 0 Innodb_os_log_pending_writes 0 Innodb_os_log_written 1461624320 Innodb_page_size 16384 Innodb_pages_created 10456 Innodb_pages_read 1379772 Innodb_pages_written 1969738 Innodb_row_lock_current_waits 0 Innodb_row_lock_time 94041908 Innodb_row_lock_time_avg 1324 Innodb_row_lock_time_max 6885 Innodb_row_lock_waits 71018 Innodb_rows_deleted 525 Innodb_rows_inserted 368856 Innodb_rows_read 1557304555 Innodb_rows_updated 104987256 Key_blocks_not_flushed 0 Key_blocks_unused 14495 Key_blocks_used 4 Key_read_requests 52709 Key_reads 15 Key_write_requests 671 Key_writes 94 Last_query_cost 0.000000 Max_used_connections 7 Not_flushed_delayed_rows 0 Open_files 16 Open_streams 0 Open_table_definitions 187 Open_tables 64 Opened_files 582769 Opened_table_definitions 0 Opened_tables 0 Prepared_stmt_count 0 Qcache_free_blocks 1023 Qcache_free_memory 11753872 Qcache_hits 12352457 Qcache_inserts 107355 Qcache_lowmem_prunes 0 Qcache_not_cached 10119746 Qcache_queries_in_cache 2750 Qcache_total_blocks 6655 Queries 23924377 Questions 2 Rpl_status NULL Select_full_join 0 Select_full_range_join 0 Select_range 0 Select_range_check 0 Select_scan 0 Slave_open_temp_tables 0 Slave_retried_transactions 0 Slave_running OFF Slow_launch_threads 0 Slow_queries 0 Sort_merge_passes 0 Sort_range 0 Sort_rows 0 Sort_scan 0 Ssl_accept_renegotiates 0 Ssl_accepts 0 Ssl_callback_cache_hits 0 Ssl_cipher Ssl_cipher_list Ssl_client_connects 0 Ssl_connect_renegotiates 0 Ssl_ctx_verify_depth 0 Ssl_ctx_verify_mode 0 Ssl_default_timeout 0 Ssl_finished_accepts 0 Ssl_finished_connects 0 Ssl_session_cache_hits 0 Ssl_session_cache_misses 0 Ssl_session_cache_mode NONE Ssl_session_cache_overflows 0 Ssl_session_cache_size 0 Ssl_session_cache_timeouts 0 Ssl_sessions_reused 0 Ssl_used_session_cache_entries 0 Ssl_verify_depth 0 Ssl_verify_mode 0 Ssl_version Table_locks_immediate 18960035 Table_locks_waited 520 Tc_log_max_pages_used 0 Tc_log_page_size 0 Tc_log_page_waits 0 Threads_cached 6 Threads_connected 1 Threads_created 7 Threads_running 1 Uptime 13580879 Uptime_since_flush_status 13580879 

If no-one can see anything obvious from there, I suppose I'll have to start timing individual queries and portions of the code.

This does not happen on pages that use few database queries, so I'm ruling out network problems.

Answer 1

First thing to check is that name resolving is disabled, and authentication is done based on IP address, not name. This can introduce huge latency for query operations.

Yes, running a query directly against the data on disk is much, much slower than fetching it from the query cache - a large proportion of your queries are being resolved from the Query cache, but making it any bigger is not going to have a huge impact.

Whether your query performance is the issue will be evident from your slow query log - if you're using anything less than 5.1, upgrade your DB so you can set a slow query threshold of 0 seconds (i.e. everything gets logged) and start using mysqldumpslow to analyse the data.

It looks as if your tables are in innodb - looking at what you've published here, there are problems with your config. Assuming this a dedicated DB server, and not using MyISAM then you need a much bigger innodb_buffer_pool_size (not shown in metrics quoted?)