ghazel commented 13 years ago

Use of uninitialized value in printf at /etc/munin/plugins/mysql_innodb_insert_buf line 1099.

Happens with mysql_innodb_insert_buf, mysql_innodb_insert_buf_size and mysql_innodb_io_pend using MySQL 5.5.8.

Here are the relevant sections of the SHOW ENGINE INNODB STATUS\G output

--------
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: 1 [0, 1, 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
5528380 OS file reads, 19874402 OS file writes, 615327 OS fsyncs
19.95 reads/s, 16384 avg bytes/read, 30.74 writes/s, 3.22 fsyncs/s

-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 206, free list len 23078, seg size 23285, 202193 merges
merged operations:
 insert 496342, delete mark 22556, delete 3840
discarded operations:
 insert 1686, delete mark 2, delete 0
Hash table size 57374437, node heap has 54332 buffer(s)
87022.67 hash searches/s, 7098.93 non-hash searches/s

kjellm commented 13 years ago

Yes, I know. I have not had time to add support for 5.5 yet. It is my top priority for the project, though.

kjellm commented 13 years ago

Fixed it for the 'InnoDB Insert Buffer Size' graph in SHA: 0868c15b8ee5396f2a8e61a14e1cf273fb587cfa

kjellm commented 13 years ago

Fxied it for the 'InnoDB IO Pending' graph in SHA: f6caf38a2369f10e38c3a0ddf8081a8cf663aa32

kjellm commented 13 years ago

Don't know how to handle the differences in SHOW ENGINE STATUS regarding the 'InnoDB Insert Buffer' graph.

OId format:

952758 inserts, 952758 merged recs, 356579 merges

New format:

merged operations:
 insert 496342, delete mark 22556, delete 3840
discarded operations:
 insert 1686, delete mark 2, delete 0

ghazel commented 13 years ago

Mark Leith explains a bit of that in the first comment here: http://www.facebook.com/note.php?note_id=460565850932

Just today, I modified the MEM agent parsing of this section for 5.5, it now includes more statistics
given the change to "change buffering", and removes the line pasted above. 

On a 5.5 instance you now see:

-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 90 merges
merged operations:
insert 229, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0

'merges' remains the same statistic (promoted to the first line), whilst we now break out
operations by type between merged operations (actual changes written to disk), and discarded
operations (changes that were in the insert buffer that are thrown away - due to the table/index
getting dropped for instance). 

"delete mark" is marking a record for deletion, "delete" is actual purging.

ghazel commented 13 years ago

There is also the Unknown section: INDIVIDUAL BUFFER POOL INFO problem with 5.5.

ghazel commented 13 years ago

An example of the 5.5 output:

----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 29783752704; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 2048919104      (458995144 + 1589923960)
    Page hash           7172584 (buffer pool 0 only)
    Dictionary cache    115766209       (114750256 + 1015953)
    File system         110832  (82672 + 28160)
    Lock system         71736872        (71718824 + 18048)
    Recovery system     0       (0 + 0)
Dictionary memory allocated 1015953
Buffer pool size        1769468
Buffer pool size, bytes 28990963712
Free buffers            1
Database pages          1672426
Old database pages      617279
Modified db pages       2923
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 31483253, not young 1915732679
4.20 youngs/s, 16.20 non-youngs/s
Pages read 50141845, created 1051953, written 69568873
7.40 reads/s, 0.60 creates/s, 0.00 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: 1672426, unzip_LRU len: 0
I/O sum[10216]:cur[8], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size        442367
Buffer pool size, bytes 7247740928
Free buffers            0
Database pages          418135
Old database pages      154331
Modified db pages       876
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8012138, not young 512929033
1.20 youngs/s, 5.00 non-youngs/s
Pages read 12839051, created 265441, written 17463949
2.60 reads/s, 0.00 creates/s, 0.00 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: 418135, unzip_LRU len: 0
I/O sum[2554]:cur[2], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size        442367
Buffer pool size, bytes 7247740928
Free buffers            1
Database pages          418057
Old database pages      154301
Modified db pages       404
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 7874890, not young 474563887
1.40 youngs/s, 4.60 non-youngs/s
Pages read 12537934, created 258941, written 17405384
1.80 reads/s, 0.00 creates/s, 0.00 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: 418057, unzip_LRU len: 0
I/O sum[2554]:cur[2], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size        442367
Buffer pool size, bytes 7247740928
Free buffers            0
Database pages          418148
Old database pages      154335
Modified db pages       774
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 7765924, not young 451795351
1.40 youngs/s, 1.80 non-youngs/s
Pages read 12311287, created 261939, written 17323009
1.40 reads/s, 0.20 creates/s, 0.00 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: 418148, unzip_LRU len: 0
I/O sum[2554]:cur[2], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size        442367
Buffer pool size, bytes 7247740928
Free buffers            0
Database pages          418086
Old database pages      154312
Modified db pages       869
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 7830301, not young 476444408
0.20 youngs/s, 4.80 non-youngs/s
Pages read 12453573, created 265632, written 17376531
1.60 reads/s, 0.40 creates/s, 0.00 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: 418086, unzip_LRU len: 0
I/O sum[2554]:cur[2], unzip sum[0]:cur[0]

ghazel commented 13 years ago

Also I'm still getting Use of uninitialized value in printf at /etc/munin/plugins/mysql line 301 on these values:

krd
krrd
key_cache_eff
qh
cs
qcache_eff
bcdu
bcu
bl_cache_eff
ib_ibuf_inserts
ib_ibuf_merged_rec
ib_ibuf_merges
ib_iop_log
ib_iop_sync
ib_iop_ibuf_aio
ib_iop_aioread
ib_iop_aiowrite

kjellm commented 13 years ago

The first 9 values (krd .. b1_cache_eff) concerns a graph in the contrib section not maintained by me: https://github.com/kjellm/munin-mysql/blob/master/contrib/Munin/MySQL/Graph/CacheEfficiency.pm

I have made a change to the Makefile so that contrib graphs don't install by default (See 0503018cd0cd726f405ca56c51eed85ca11ad92d).

kjellm commented 13 years ago

111293966ccd6e8df6c1347cb0f9a8b4025c0266 fixes the problem with the INDIVIDUAL BUFFER POOL INFO section

kjellm commented 13 years ago

Not sure about why you the ib_iop values are missing. What does your "FILE I/O" section look like?

ghazel commented 13 years ago

--------
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 (read thread)
I/O thread 7 state: waiting for completed aio requests (read thread)
I/O thread 8 state: waiting for completed aio requests (read thread)
I/O thread 9 state: waiting for completed aio requests (read thread)
I/O thread 10 state: waiting for completed aio requests (read thread)
I/O thread 11 state: waiting for completed aio requests (read thread)
I/O thread 12 state: waiting for completed aio requests (read thread)
I/O thread 13 state: waiting for completed aio requests (read thread)
I/O thread 14 state: waiting for completed aio requests (read thread)
I/O thread 15 state: waiting for completed aio requests (read thread)
I/O thread 16 state: waiting for completed aio requests (read thread)
I/O thread 17 state: waiting for completed aio requests (read thread)
I/O thread 18 state: waiting for completed aio requests (write thread)
I/O thread 19 state: waiting for completed aio requests (write thread)
I/O thread 20 state: waiting for completed aio requests (write thread)
I/O thread 21 state: waiting for completed aio requests (write thread)
I/O thread 22 state: waiting for completed aio requests (write thread)
I/O thread 23 state: waiting for completed aio requests (write thread)
I/O thread 24 state: waiting for completed aio requests (write thread)
I/O thread 25 state: waiting for completed aio requests (write thread)
I/O thread 26 state: waiting for completed aio requests (write thread)
I/O thread 27 state: waiting for completed aio requests (write thread)
I/O thread 28 state: waiting for completed aio requests (write thread)
I/O thread 29 state: waiting for completed aio requests (write thread)
I/O thread 30 state: waiting for completed aio requests (write thread)
I/O thread 31 state: waiting for completed aio requests (write thread)
I/O thread 32 state: waiting for completed aio requests (write thread)
I/O thread 33 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 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
52896612 OS file reads, 84745280 OS file writes, 8632738 OS fsyncs
2 pending preads, 0 pending pwrites
74.82 reads/s, 16384 avg bytes/read, 231.46 writes/s, 11.33 fsyncs/s

kjellm commented 13 years ago

09a1505d3aa195f00150b9a41df57371ac5d30f2 should fix the problem with missing ib_iop* values

ghazel commented 13 years ago

I dug in to the 'InnoDB Insert Buffer' graph change: http://bazaar.launchpad.net/~mysql/mysql-server/mysql-trunk/revision/0.5.4

For reference:

OId format:

952758 inserts, 952758 merged recs, 356579 merges

New format:

Ibuf: size 206, free list len 23078, seg size 23285, 202193 merges
merged operations:
 insert 496342, delete mark 22556, delete 3840
discarded operations:
 insert 1686, delete mark 2, delete 0

So I believe, to compute the old values from the new format:

"#{merged operations inserts} inserts, #{merged operations inserts + discarded operations inserts} merged recs, #{merges} merges"

However it's probably a good idea just to modify the Insert Buffer graph and plot the new stats directly.

kjellm commented 13 years ago

Cool. Will take a look at it after my summer brake.

ghost commented 13 years ago

According to ghazel logic:

@@ -1504,16 +1504,16 @@ sub parse_insert_buffer_and_adaptive_hash_index { parse_section( sub {

m/\G(\d+) inserts, (\d+) merged recs, (\d+) merges\n/gc && do {
m/\Gmerged operations:\n insert (\d+), delete mark \d+, delete \d+\ndiscarded operations:\n insert (\d+), delete mark \d+, delete \d+\n/gc && do { $data->{ib_ibuf_inserts} = $1;
$data->{ib_ibuf_merged_rec} = $2;
$data->{ib_ibuf_merges} = $3;
$data->{ib_ibuf_merged_rec} = $1 + $2; return 1; };
m/\GIbuf: size (\d+), free list len (\d+), seg size (\d+),\n/gc && do {
m/\GIbuf: size (\d+), free list len (\d+), seg size (\d+), (\d+) merges\n/gc && do { $data->{ib_ibuf_size} = $1; $data->{ib_ibuf_free_len} = $2; $data->{ib_ibuf_seg_size} = $3;
$data->{ib_ibuf_merges} = $4; return 1; }; }

ovizii commented 9 years ago

I know this is an old issue but my mysql_ stopped working a few days ago and in the error files I find this:

2014/11/19-00:00:02 [501388] Error output from mysql_innodb_bpool_act: 2014/11/19-00:00:02 [501388] Unknown section: INDIVIDUAL BUFFER POOL INFO at /etc/munin/plugins/mysql_innodb_bpool_act line 1099. 2014/11/19-00:00:02 [501388] Service 'mysql_innodb_bpool_act' exited with status 255/0.

And those errors repeat a lot.

Running Debian 64bit, latest version and I've installed munin and its plugins via apt-get

Here are my graphs: https://foo.dj/munin/stratoserver.net/h2118175.stratoserver.net/index.html#mysql2

Server version: 5.6.21-1~dotdeb.1-log (Debian)

kjellm commented 9 years ago

This is not an issue in the version of the plugin hosted here. Report the issue to http://munin-monitoring.org.

ovizii commented 9 years ago

Oh, sorry for that, this page was the only one that came up when googling the exact error message :-/ I'll head over there, thanks for the pointer.

kjellm commented 9 years ago

No problem. I know it is confusing.

ovizii commented 9 years ago

Damn, I foudn a trac ticket here: http://munin-monitoring.org/ticket/1647 looks like its the same problem but I can't post my message there as my IP is apparently blacklisted. Gotta wait 24h now and hope my ISP gives me another one ;-)

danvaida commented 9 years ago

sorry for posting in a closed issue: @ovizii have you managed to get this sorted? thanks.

ovizii commented 9 years ago

@danvaida - no I didn't, simply gave up. Couldn't figure it out on my own, no hints as to what is wrong, just stopped working. I guess I'll have to live with this until maybe a future version sorts this out again.

danvaida commented 9 years ago

did you see this https://github.com/munin-monitoring/munin/pull/109/ ?

ovizii commented 9 years ago

Ah, my mistake, I thought I had the munin version that includes that fix already (apparently it should be included in: 2.1.3.) and only now when you asked I realized I am running munin: 2.0.25-1~bpo70+1

Let me check if I can upgrade my munin or apply those patched manually.

The only thing I am wondering about is why it was working before???

ovizii commented 9 years ago

I'm now running: This page was generated by Munin version 2.1.9-1 from the experimental Debian branch and its seems I still have the exact same problem:

2015/01/05-19:30:15 [824524] Unknown section: INDIVIDUAL BUFFER POOL INFO at /etc/munin/plugins/mysql_slow line 1099. 2015/01/05-19:30:15 [824524] Service 'mysql_slow' exited with status 255/0. 2015/01/05-19:30:15 [824524] Error output from mysql_tmp_tables: 2015/01/05-19:30:15 [824524] Unknown section: INDIVIDUAL BUFFER POOL INFO at /etc/munin/plugins/mysql_tmp_tables line 1099. 2015/01/05-19:30:15 [824524] Service 'mysql_tmp_tables' exited with status 255/0. 2015/01/05-19:30:17 [824524] Error output from mysql_innodb_bpool: 2015/01/05-19:30:17 [824524] Unknown section: INDIVIDUAL BUFFER POOL INFO at /etc/munin/plugins/mysql_innodb_bpool line 1099. 2015/01/05-19:30:17 [824524] Service 'mysql_innodb_bpool' exited with status 255/0. 2015/01/05-19:32:11 Server closing!

Will probably revert back to the stable munin version asap :-(

danvaida commented 9 years ago

do you have line "'INDIVIDUAL BUFFER POOL INFO' => &skip," ? it's on line 1075 in commit https://github.com/y-ken/munin/commit/9f53020cc7aa5338b9983cab3c1f233ffd349576

ovizii commented 9 years ago

No I don't check here: http://screencast.com/t/Ou4e6Aijl (and that is the only occurance in the plugin file :-(

So what I did was this: 'apt-get install -t experimental munin munin-common munin-doc munin-node munin-plugins-core munin-plugins-extra -u'

which installed Munin version 2.1.9-1

ovizii commented 9 years ago

and btw. my munin install is now completely dead with version 2.1.9-1 :-/ the only thing I can find in the lgos that looks suspicious is: The following errors were reported by munin-node-configure --shell --newer 2.0.6

FATAL: version '2.0.6' was not found in the plugin history file

Jan 06 20:50:35 - Starting munin-node-configure --shell --newer 2.0.6

Any ideas which logs to check and how to debug? It just stopped working => https://foo.dj/munin/stratoserver.net/h2118175.stratoserver.net/index.html

Next I started playing around with: munin-node-configure --suggest and found a few unused plugins that were giving errors so I deleted them in the hopes of fixing this problem. And indeed it started working again but a few other modules now stopped. sigh gotta go fix those now, check the link above.

P.S. MYSQL now seems to be working too.

ovizii commented 9 years ago

I should have staid far away from this, it seems this fiddling around of mine has broken munin insofar as it doesn't get updates from my other server, gettign emaisl from cron: Cron munin@h2118175 if [ -x /usr/bin/munin-cron ]; then /usr/bin/munin-cron; fi 2015-01-09 11:36:01 [critical]: [FATAL] Socket read from server.quilombobrasil.com failed. Terminating process.

Busy rolling it all back :-(

kjellm / munin-mysql

Support MySQL 5.5 #34

FATAL: version '2.0.6' was not found in the plugin history file