Re: Thoughts on Logical Log use requested
Posted in 2006
Topics: Stored Procedures & SPL, Logging & Checkpoints
Ok, here's some information as requested by TBP & OTC,
The onstat -l was taken today (unable to run cmd on Sun), the list of log
times for Sunday (yesterday) follow that.
Choosing one of the logs at random (No. 160439) it filled in 10 mins 3 secs
and consists of (among others)
49215 HINSERT
51256 BEGIN
50990 COMMIT
56238 HUPDAT
20 BTMERGE
915 BTSPLIT
0 CHALLOC
0 CKPOINT (log filled between checkpoints - CKPTINTVL 900 secs)
266 ROLLBACK
onstat -l
Informix Dynamic Server Version 7.31.FD7 -- On-Line -- Up 5 days
21:17:50 -- 16303104 Kbytes
Physical Logging
Buffer bufused bufsize numpages numwrits pages/io
P-1 1 64 566304 9695 58.41
phybegin physize phypos phyused %used
200035 1020000 1005727 9101 0.89
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
L-2 0 64 7276898 892936 838083 8.1 1.1
Subsystem numrecs Log Space used
OLDRSAM 7276898 435137336
address number flags uniqid begin size used
%used
10dca21a0 1 U-B---- 160428 1100035 51197 51197
100.00
10dca21c0 2 U-B---- 160429 1200035 51197 51197
100.00
10dca21e0 3 U-B---- 160430 110c832 51197 51197
100.00
10dca2200 4 U-B---- 160431 120c832 51197 51197
100.00
10dca2220 5 U-B---- 160432 111902f 51197 51197
100.00
10dca2240 6 U-B---- 160433 121902f 51197 51197
100.00
10dca2260 7 U-B---- 160434 112582c 51197 51197
100.00
10dca2280 8 U-B---- 160435 122582c 51197 51197
100.00
10dca22a0 9 U-B---- 160436 1132029 51197 51197
100.00
10dca22c0 10 U-B---- 160437 1232029 51197 51197
100.00
10dca22e0 11 U-B---- 160438 113e826 51197 51197
100.00
10dca2300 12 U-B---- 160439 123e826 51197 51197
100.00
10dca2320 13 U-B---- 160440 114b023 51197 51197
100.00
10dca2340 14 U-B---- 160441 124b023 51197 51197
100.00
10dca2360 15 U-B---- 160442 1157820 51197 51197
100.00
10dca2380 16 U-B---- 160443 1257820 51197 51197
100.00
10dca23a0 17 U-B---- 160444 116401d 51197 51197
100.00
10dca23c0 18 U-B---- 160445 126401d 51197 51197
100.00
10dca23e0 19 U-B---- 160446 117081a 51197 51197
100.00
10dca2400 20 U-B---- 160447 127081a 51197 51197
100.00
10dca2420 21 U-B---- 160448 117d017 51197 51197
100.00
10dca2440 22 U-B---- 160449 127d017 51197 51197
100.00
10dca2460 23 U-B---- 160450 1189814 51197 51197
100.00
10dca2480 24 U-B---- 160451 1289814 51197 51197
100.00
10dca24a0 25 U-B---- 160452 1196011 51197 51197
100.00
10dca24c0 26 U-B---- 160453 1296011 51197 51197
100.00
10dca24e0 27 U-B---- 160454 11a280e 51197 51197
100.00
10dca2500 28 U-B---- 160455 12a280e 51197 51197
100.00
10dca2520 29 U-B---- 160456 11af00b 51197 51197
100.00
10dca2540 30 U-B---- 160457 12af00b 51197 51197
100.00
10dca2560 31 U-B---- 160458 11bb808 51197 51197
100.00
10dca2580 32 U-B---- 160459 12bb808 51197 51197
100.00
10dca25a0 33 U-B---- 160460 11c8005 51197 51197
100.00
10dca25c0 34 U-B---- 160461 12c8005 51197 51197
100.00
10dca25e0 35 U-B---- 160462 11d4802 51197 51197
100.00
10dca2600 36 U-B---- 160463 12d4802 51197 51197
100.00
10dca2620 37 U-B---- 160464 11e0fff 51197 51197
100.00
10dca2640 38 U-B---- 160465 12e0fff 51197 51197
100.00
10dca2660 39 U-B---- 160466 11ed7fc 51197 51197
100.00
10dca2680 40 U-B---- 160467 12ed7fc 51197 51197
100.00
10dca26a0 41 U-B---- 160468 6900035 51197 51197
100.00
10dca26c0 42 U-B---- 160469 6b00035 51197 51197
100.00
10dca26e0 43 U-B---- 160470 690c832 51197 35459
69.26
10dca2700 44 U-B---- 160471 6b0c832 51197 51197
100.00
10dca2720 45 U-B---- 160472 691902f 51197 51197
100.00
10dca2740 46 U-B---- 160473 6b1902f 51197 51197
100.00
10dca2760 47 U-B---- 160474 692582c 51197 51197
100.00
10dca2780 48 U-B---- 160475 6b2582c 51197 51197
100.00
10dca27a0 49 U-B---- 160476 6932029 51197 51197
100.00
10dca27c0 50 U-B---- 160477 6b32029 51197 51197
100.00
10dca27e0 51 U---C-L 160478 693e826 51197 20439
39.92
10dca2800 52 U-B---- 160399 6b3e826 51197 51197
100.00
10dca2820 53 U-B---- 160400 694b023 51197 51197
100.00
10dca2840 54 U-B---- 160401 6b4b023 51197 51197
100.00
10dca2860 55 U-B---- 160402 6957820 51197 51197
100.00
10dca2880 56 U-B---- 160403 6b57820 51197 51197
100.00
10dca28a0 57 U-B---- 160404 696401d 51197 51197
100.00
10dca28c0 58 U-B---- 160405 6b6401d 51197 51197
100.00
10dca28e0 59 U-B---- 160406 697081a 51197 51197
100.00
10dca2900 60 U-B---- 160407 6b7081a 51197 51197
100.00
10dca2920 61 U-B---- 160408 697d017 51197 41439
80.94
10dca2940 62 U-B---- 160409 6b7d017 51197 51197
100.00
10dca2960 63 U-B---- 160410 6989814 51197 51197
100.00
10dca2980 64 U-B---- 160411 6b89814 51197 51197
100.00
10dca29a0 65 U-B---- 160412 6996011 51197 51197
100.00
10dca29c0 66 U-B---- 160413 6b96011 51197 51197
100.00
10dca29e0 67 U-B---- 160414 69a280e 51197 51197
100.00
10dca2a00 68 U-B---- 160415 6ba280e 51197 51197
100.00
10dca2a20 69 U-B---- 160416 69af00b 51197 51197
100.00
10dca2a40 70 U-B---- 160417 6baf00b 51197 51197
100.00
10dca2a60 71 U-B---- 160418 69bb808 51197 51197
100.00
10dca2a80 72 U-B---- 160419 6bbb808 51197 51197
100.00
10dca2aa0 73 U-B---- 160420 69c8005 51197 51197
100.00
10dca2ac0 74 U-B---- 160421 6bc8005 51197 51197
100.00
10dca2ae0 75 U-B---- 160422 69d4802 51197 51197
100.00
10dca2b00 76 U-B---- 1604
Colin Dawson wrote:
> Ok, here's some information as requested by TBP & OTC,
>
> The onstat -l was taken today (unable to run cmd on Sun), the list of
> log times for Sunday (yesterday) follow that.
>
> Choosing one of the logs at random (No. 160439) it filled in 10 mins 3
> secs and consists of (among others)
>
> 49215 HINSERT
> 51256 BEGIN
> 50990 COMMIT
> 56238 HUPDAT
> 20 BTMERGE
> 915 BTSPLIT
> 0 CHALLOC
> 0 CKPOINT (log filled between checkpoints - CKPTINTVL 900 secs)
> 266 ROLLBACK
>
> onstat -l
> Informix Dynamic Server Version 7.31.FD7 -- On-Line -- Up 5 days
> 21:17:50 -- 16303104 Kbytes>
> Physical Logging
> Buffer bufused bufsize numpages numwrits pages/io
> P-1 1 64 566304 9695 58.41
> phybegin physize phypos phyused %used
> 200035 1020000 1005727 9101 0.89
>
> Logical Logging
> Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
> L-2 0 64 7276898 892936 838083 8.1 1.1
> Subsystem numrecs Log Space used
> OLDRSAM 7276898 435137336
>
> address number flags uniqid begin size
> used %used
> 10dca21a0 1 U-B---- 160428 1100035 51197 51197
> 100.00
> 10dca21c0 2 U-B---- 160429 1200035 51197 51197
> 100.00
> 10dca21e0 3 U-B---- 160430 110c832 51197 51197
> 100.00
> 10dca2200 4 U-B---- 160431 120c832 51197 51197
> 100.00
> 10dca2220 5 U-B---- 160432 111902f 51197 51197
> 100.00
> 10dca2240 6 U-B---- 160433 121902f 51197 51197
> 100.00
> 10dca2260 7 U-B---- 160434 112582c 51197 51197
> 100.00
<snip>
Well, just interesting to look at what transaction mix you have :
51,256 Begins
and
51,256 (50,990 commits plus 266 rollbacks)
And it looks like roughly one insert and one update per transaction.
So, you HAVE to have 51,250 minute transactions in an unbuffered logging
database i.e. about 100 pretty small transactions a second (100 * 60 *
10 = 60,000).
You are getting about 2 complete transactions per flush (8 records per
page - "begin, insert, update, commit" * 2); if there were NO overhead
(i.e. 0.9 waste of the 2nd page on each flush), you would consume :
Each transaction is using roughly 1k of log space
60,000 1k log usage transactions in 10 minutes = 60Mb
Seems like you are doing okay, bearing in mind the "absolute necessity
to run with unbuffered logging".
Only suggestions really would be to consider :
1. Are these "minute" transactions a must? Are they really business
transactions - or just application driven.
2. What is the requirement for "unbuffered logging"?
Food for thought rather than a panacea, but I think that you should look
beyond IDS for your solution.