MySQL queries running Extraordinarily slow on Fedora-15?

[Vector]

Hey guys, i'm not sure if this is because i'm having problems with my Raid setup, which mysql is running on, or if it is unrelated, but is anyone else noticing that mysql is VERY slow on Fedora 15?

[smr54]

No, but I've only used it for a very tiny wordpress database while looking into using wordpress for something at work.

So, don't take that as an authoritative answer.

[Vector]

I've been building and running this database for about 2 years now, without problems, and i've got it fairly fine tuned. Now my slow_query_log is going nuts, logging queries at between 4 and 177 SECONDS! It wasn't like this before my upgrade; it was VERY FAST before. IInnoDB Lock times are averaving 0.000058 seconds, so why is the query at 177.* seconds?

Here's a snippet of my slow_log:

# Time: 110605  0:00:16
# User@Host: ionisis[ionisis] @ localhost []
# Query_time: 4.091009  Lock_time: 0.000043 Rows_sent: 38  Rows_examined: 39
SET timestamp=1307246416;
call User_Environment_Build('156748001296551854','12962693550254944','2011-06-05 04:00:12');
# Time: 110605  0:00:20
# User@Host: ionisis[ionisis] @ localhost []
# Query_time: 3.810009  Lock_time: 0.000033 Rows_sent: 2  Rows_examined: 52
SET timestamp=1307246420;
call User_IPPC_Display('156748001296551854','','2','0','2011-06-05 04:00:12','c','3090779173');
# Time: 110605  0:00:21
# User@Host: ionisis[ionisis] @ localhost []
# Query_time: 41.346450  Lock_time: 0.000042 Rows_sent: 1  Rows_examined: 271
SET timestamp=1307246421;
call User_WMMS_Multimedia_Display('164733001258091455','12985179360690753','0','');

Here's my.cnf:

[mysqld]
datadir=/R5/system/sql
socket=/var/lib/mysql/mysql.sock
user=mysql
symbolic-links=0


# Start Changes #
profiling = 1
max_connections=500
general_log = 0
general_log_file = log_query
log-error = log_error
slow_query_log = 1
long_query_time = 1
slow_query_log_file = log_slow

query_cache_limit = 1048576
query_cache_min_res_unit = 4096
query_cache_wlock_invalidate = false
query_cache_size = 100663296
query_cache_type = 1
# End Changes #


[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

Here's show engine innodb status:

| InnoDB |      | 
=====================================
110605  1:01:03 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 47 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2590 1_second, 2589 sleeps, 253 10_second, 71 background, 71 flush
srv_master_thread log flush and writes: 2874
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 23820, signal count 16470
Mutex spin waits 18431, rounds 436622, OS waits 13123
RW-shared spins 1132, rounds 61020, OS waits 2033
RW-excl spins 3799, rounds 260818, OS waits 8546
Spin rounds per wait: 23.69 mutex, 53.90 RW-shared, 68.65 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 2659CCC
Purge done for trx's n:o < 2659CC7 undo n:o < 0
History list length 1472
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started, process no 15947, OS thread id 140635081459456
MySQL thread id 593, query id 333588 localhost root
show engine innodb status
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
3499 OS file reads, 63566 OS file writes, 26011 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 3.34 writes/s, 1.34 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7, 3 merges
merged operations:
 insert 4, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 276707, node heap has 106 buffer(s)
173.25 hash searches/s, 67.91 non-hash searches/s
---
LOG
---
Log sequence number 6081096637
Log flushed up to   6081096637
Last checkpoint at  6081096637
0 pending log writes, 0 pending chkp writes
24545 log i/o's done, 1.26 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137363456; in additional pool allocated 0
Dictionary memory allocated 749535
Buffer pool size   8192
Free buffers       4597
Database pages     3489
Old database pages 1307
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 3360, created 129, written 38006
0.00 reads/s, 0.00 creates/s, 2.02 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s
LRU len: 3489, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 15947, id 140635091183360, state: sleeping
Number of rows inserted 32274, updated 324, deleted 2, read 1639759
3.62 inserts/s, 0.02 updates/s, 0.00 deletes/s, 339.63 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

I just wonder if this has anything to do with the problems i'm having with my Raid not mounting on boot. I'm going to google those "waiting for io..." messages...

[Vector]

I completely uninstalled all mysql stuff. I completely removed the entire sql directory. I completely reinstalled mysql*. I imported the database dump. Same situation.

I'm starting to notice that there are SEVERAL other people with a similar issue, for which a bug has been filed, but it is not the SAME issue. It seems that this issue happens with almost any stored routine, but is much worse for stored routines that use TEMPORARY TABLES (i know, you're supposed to use engine=memory, but that can't ALWAYS be done, AND, it does not apply here, because this was very fast on mysql 5.1.*).


None of this looks right (snippet from show global status), ESPECIALLY the InnoDB Data Written (or whatever that huge number was) as my sites are not that busy (the one's in my signature, they're just a couple of small sites), not to mention that i just restarted the server again about 10 minutes ago:

| Innodb_buffer_pool_pages_data            | 1334        |
| Innodb_buffer_pool_pages_dirty           | 119         |
| Innodb_buffer_pool_pages_flushed         | 31136       |
| Innodb_buffer_pool_pages_free            | 6845        |
| Innodb_buffer_pool_pages_misc            | 13          |
| Innodb_buffer_pool_pages_total           | 8192        |
| Innodb_buffer_pool_read_ahead            | 0           |
| Innodb_buffer_pool_read_ahead_evicted    | 0           |
| Innodb_buffer_pool_read_requests         | 841005      |
| Innodb_buffer_pool_reads                 | 1184        |
| Innodb_buffer_pool_wait_free             | 0           |
| Innodb_buffer_pool_write_requests        | 311553      |
| Innodb_data_fsyncs                       | 12712       |
| Innodb_data_pending_fsyncs               | 1           |
| Innodb_data_pending_reads                | 0           |
| Innodb_data_pending_writes               | 0           |
| Innodb_data_read                         | 21647360    |
| Innodb_data_reads                        | 1198        |
| Innodb_data_writes                       | 28088       |
| Innodb_data_written                      | 533303296   |
| Innodb_dblwr_pages_written               | 15568       |
| Innodb_dblwr_writes                      | 312         |
| Innodb_have_atomic_builtins              | ON          |
| Innodb_log_waits                         | 0           |
| Innodb_log_write_requests                | 42411       |
| Innodb_log_writes                        | 11992       |
| Innodb_os_log_fsyncs                     | 12131       |
| Innodb_os_log_pending_fsyncs             | 1           |
| Innodb_os_log_pending_writes             | 0           |
| Innodb_os_log_written                    | 23118848    |
| Innodb_page_size                         | 16384       |
| Innodb_pages_created                     | 147         |
| Innodb_pages_read                        | 1187        |
| Innodb_pages_written                     | 15568       |
| 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                     | 10941       |
| Innodb_rows_read                         | 85689       |
| Innodb_rows_updated                      | 196         |
| Innodb_truncated_status_writes           | 0           |
| Key_blocks_not_flushed                   | 0           |
| Key_blocks_unused                        | 6466        |
| Key_blocks_used                          | 232         |
| Key_read_requests                        | 35048       |
| Key_reads                                | 232         |
| Key_write_requests                       | 0           |
| Key_writes                               | 0           |
| Last_query_cost                          | 0.000000    |
| Max_used_connections                     | 7           |
| Not_flushed_delayed_rows                 | 0           |
| Open_files                               | 76          |
| Open_streams                             | 0           |
| Open_table_definitions                   | 174         |
| Open_tables                              | 224         |
| Opened_files                             | 12968       |
| Opened_table_definitions                 | 8453        |
| Opened_tables                            | 8509        |
...
| Qcache_free_blocks                       | 0           |
| Qcache_free_memory                       | 0           |
| Qcache_hits                              | 0           |
| Qcache_inserts                           | 0           |
| Qcache_lowmem_prunes                     | 0           |
| Qcache_not_cached                        | 0           |
| Qcache_queries_in_cache                  | 0           |
| Qcache_total_blocks                      | 0           |
| Queries                                  | 150701      |

[Vector]

I found out there are numerous bugs relating to stored routines that use temp tables or text variables; so, this would appear to be a bug. They said the bug was supposed to be fixed in an upcoming release, but i was having so many problems with my upgrade to F15 (raid not working, workbench not working, sql-server not working) that i just went back to 14.

So, that solves this mystery.

[liquidox]

I am experiencing this same issue, somewhat ridiculous, the main database server on Fedora 15 runs like mud.