Syndicate

Syndicate content

IBM Informix: Long Transaction aborted umgehen und monitoren

Submitted by Malte Sukopp on Mon, 2009-07-13 09:44

(german content)

Wenn eine Transaktion soviel Prozent des gesamten Logical Logspaces benötigt, wie durch den onconfig-Parameter Long-Transaction High-Watermark (LTXHWM) definiert ist, wird diese Transaktion zurückgerollt. Überschreitet sie dabei die durch die Long-Transaction Exclusive High-Watermark (LTXEHWM) definierte Menge an Logical Logspace, werden nahezu alle anderen Datenbankaktionen zugunsten des Rollbacks eingefroren. Wie kann man sich davor schützen?

Der Rollback einer Transaktion aufgrund ihrer Länge ist zunächst einmal ein normaler Vorgang in einer Datenbank. Wann das passieren soll, lässt sich durch die LTXHWM einstellen. Ärgerlich wird es dann, wenn die Long Transaction die LTXEHWM erreicht: Das System steht quasi, und man weiß nicht, wie lange noch. Doch das lässt sich durchaus grob ermitteln, das folgende Beispiel zeigt, wie.

Eine Transaktion beginnt immer in einem bestimmten Logical Logfile. Diese lassen sich mit "onstat -l" ansehen:

IBM Informix Dynamic Server Version 10.00.HC6     -- On-Line -- Up 01:08:18 -- 450456 Kbytes

Physical Logging
Buffer bufused  bufsize  numpages   numwrits   pages/io
  P-1  0        64       42974      1617       26.58
      phybegin         physize    phypos     phyused    %used
      1:263            50000      5216       0          0.00

Logical Logging
Buffer bufused  bufsize  numrecs    numpages   numwrits   recs/pages pages/io
  L-3  0        64       3547643    104146     1802       34.1       57.8
        Subsystem    numrecs    Log Space used
        OLDRSAM      3547643    209940824

address  number   flags    uniqid   begin                size     used    %used
e15648b0 7        U---C-L  49       2:53                10000        6     0.06
e15648f8 8        U-B----  38       2:10053             10000    10000   100.00
e1564940 9        U-B----  39       2:20053             10000    10000   100.00
e1564988 10       U-B----  40       2:30053             10000    10000   100.00
e15649d0 11       U-B----  41       2:40053             10000    10000   100.00
e1564a18 12       U-B----  42       2:50053             10000    10000   100.00
e1564a60 13       U-B----  43       2:60053             10000    10000   100.00
e1564aa8 14       U-B----  44       2:70053             10000    10000   100.00
e1564af0 15       U-B----  45       2:80053             10000    10000   100.00
e1564b38 16       U-B----  48       2:90053              9947        1     0.01
 10 active, 10 total

Derzeit arbeitet das System im Logical Logfile mit der uniqid 49, zu sehen am "C"-Flag in der 3. Spalte ("current"). Das Beispielsystem arbeitet mit DYNAMIC_LOGS 2, was es dem Datenbankserver ermöglicht, bei einer für den Rollback nicht ausreichenden Menge von Logical Logfiles dynamisch neue hinzuzufügen. LTXHWM steht auf 70, LTXEHWM auf 80.

Es kommt nun ein update auf eine große Tabelle ins System, welchen man mit "onstat -x" beobachten kann:

IBM Informix Dynamic Server Version 10.00.HC6     -- On-Line -- Up 01:12:58 -- 450456 Kbytes

Transactions
address  flags userthread locks  beginlg curlog  logposit   isol    retrys coord
e1554018 A---- e152a018   0      0       49      0x5200     COMMIT  0
e1554220 A---- e152a550   0      0       0       0x0        COMMIT  0
e1554428 A---- e152aa88   0      0       0       0x0        COMMIT  0
e1554630 A---- e152afc0   0      0       0       0x0        COMMIT  0
e1554838 A---- e152b4f8   0      0       0       0x0        COMMIT  0
e1554a40 A---- e152ba30   0      0       0       0x0        COMMIT  0
e1554c48 A---- e152bf68   0      0       0       0x0        COMMIT  0
e1554e50 A---- e152c4a0   0      0       0       0x0        COMMIT  0
e1555058 A---- e152c9d8   0      0       0       0x0        COMMIT  0
e1555260 A---- e152cf10   0      0       0       0x0        COMMIT  0
e1555468 A---- e152d448   0      0       0       0x0        COMMIT  0
e1555878 A---- e152e3f0   0      0       0       0x0        COMMIT  0
e1555a80 A-B-- e152deb8   340    49      49      0x255660   COMMIT  0
e1555c88 A---- e152e928   0      0       0       0x0        COMMIT  0
 14 active, 128 total, 15 maximum concurrent

Das Update beginnt in Logical Logfile 49 (Spalte beginlg), und arbeitet derzeit auch in diesem Logfile (curlog).

Tip:
Die Spalte "address" aus "onstat -x" korrespondiert mit der Spalte "address" im onstat -u. So lässt sich leicht ein Zusammenhang zwischen dieser Transaktion und der zugehörigen Session-ID herstellen.

Bei erreichen des 57ten Logical Logiles wird die LTXHWM überschritten, und die Transaktion wird zurückgerollt:

onstat -l:

IBM Informix Dynamic Server Version 10.00.HC6     -- On-Line (LONGTX) -- Up 01:30:21 -- 458648 Kbytes

Physical Logging
Buffer bufused  bufsize  numpages   numwrits   pages/io
  P-1  0        64       62060      2030       30.57
      phybegin         physize    phypos     phyused    %used
      1:263            50000      24715      0          0.00

Logical Logging
Buffer bufused  bufsize  numrecs    numpages   numwrits   recs/pages pages/io
  L-2  0        64       5729995    188670     3133       30.4       60.2
        Subsystem    numrecs    Log Space used
        OLDRSAM      5729995    380573600

address  number   flags    uniqid   begin                size     used    %used
e15648b0 7        U-B----  49       2:53                10000    10000   100.00
e15648f8 8        U-B----  50       2:10053             10000    10000   100.00
e1564940 9        U-B----  51       2:20053             10000    10000   100.00
e1564988 10       U-B----  52       2:30053             10000    10000   100.00
e15649d0 11       U-B----  53       2:40053             10000    10000   100.00
e1564a18 12       U-B----  54       2:50053             10000    10000   100.00
e1564a60 13       U-B----  55       2:60053             10000    10000   100.00
e1564aa8 14       U-B----  56       2:70053             10000    10000   100.00
e1564af0 15       U---C-L  57       2:80053             10000     4530    45.30
e1564b38 16       U-B----  48       2:90053              9947        1     0.01
 10 active, 10 total

onstat -x:

IBM Informix Dynamic Server Version 10.00.HC6     -- On-Line (LONGTX) -- Up 01:30:36 -- 458648 Kbytes


Transactions
address  flags userthread locks  beginlg curlog  logposit   isol    retrys coord
e1554018 A---- e152a018   0      0       57      0x11b1018  COMMIT  0
e1554220 A---- e152a550   0      0       0       0x0        COMMIT  0
e1554428 A---- e152aa88   0      0       0       0x0        COMMIT  0
e1554630 A---- e152afc0   0      0       0       0x0        COMMIT  0
e1554838 A---- e152b4f8   0      0       0       0x0        COMMIT  0
e1554a40 A---- e152ba30   0      0       0       0x0        COMMIT  0
e1554c48 A---- e152bf68   0      0       0       0x0        COMMIT  0
e1554e50 A---- e152c4a0   0      0       0       0x0        COMMIT  0
e1555058 A---- e152c9d8   0      0       0       0x0        COMMIT  0
e1555260 A---- e152cf10   0      0       0       0x0        COMMIT  0
e1555468 A---- e152d448   0      0       0       0x0        COMMIT  0
e1555878 A---- e152e3f0   0      0       0       0x0        COMMIT  0
e1555a80 A-R-- e152deb8   41754  49      57      0xb32774   COMMIT  0
e1555c88 A---- e152e928   0      0       0       0x0        COMMIT  0
 14 active, 128 total, 15 maximum concurrent

beginlg zeigt nach wie vor 49 an, curlog zeigt 57, das aktuelle Logical Logfile.
Im online.log wird vermerkt:

15:10:12  Aborting Long Transaction: tx 0xe1555a80 username: informix uid: 104

Für den Rollback wird mehr Logical Logspace benötigt, das System wird geblocked, um ein neues Logical Logfile hinzuzufügen:

IBM Informix Dynamic Server Version 10.00.HC6     -- On-Line (LONGTX) -- Up 01:33:19 -- 458648 Kbytes
Blocked:DYNAMIC_LOG

Als nächstes wird die LTXEHWM überschritten, das System wird erneut geblocked, und steht quasi. Das neue Logical Logfile mit der Nummer 1 ist hinter dem aktuellen Logical Logfile 16 (uniqid 58) angelegt, und steht zur Verfügung:

IBM Informix Dynamic Server Version 10.00.HC6     -- On-Line (LONGTX) -- Up 01:33:39 -- 458648 Kbytes
Blocked:LONGTX

Physical Logging
Buffer bufused  bufsize  numpages   numwrits   pages/io
  P-1  29       64       69260      2216       31.25
      phybegin         physize    phypos     phyused    %used
      1:263            50000      32105      1019       2.04

Logical Logging
Buffer bufused  bufsize  numrecs    numpages   numwrits   recs/pages pages/io
  L-1  39       64       6082860    195455     3240       31.1       60.3
        Subsystem    numrecs    Log Space used
        OLDRSAM      6082860    394297796

address  number   flags    uniqid   begin                size     used    %used
e15648b0 7        U-B----  49       2:53                10000    10000   100.00
e15648f8 8        U-B----  50       2:10053             10000    10000   100.00
e1564940 9        U-B----  51       2:20053             10000    10000   100.00
e1564988 10       U-B----  52       2:30053             10000    10000   100.00
e15649d0 11       U-B----  53       2:40053             10000    10000   100.00
e1564a18 12       U-B----  54       2:50053             10000    10000   100.00
e1564a60 13       U-B----  55       2:60053             10000    10000   100.00
e1564aa8 14       U-B----  56       2:70053             10000    10000   100.00
e1564af0 15       U-B----  57       2:80053             10000    10000   100.00
e1564b38 16       U---C-L  58       2:90053              9947     1315    13.22
e1f50fb8 1        A------  0        1:58795              9973        0     0.00
 11 active, 11 total

Der onstat -x läuft nun in der Spalte "curlog" rückwärts bis zur 49, da er alle bisherigen Aktionen zurückrollt:

IBM Informix Dynamic Server Version 10.00.HC6     -- On-Line (LONGTX) -- Up 01:37:55 -- 458648 Kbytes
Blocked:LONGTX

Transactions
address  flags userthread locks  beginlg curlog  logposit   isol    retrys coord
e1554018 A---- e152a018   0      0       59      0x1dc4f0   COMMIT  0
e1554220 A---- e152a550   0      0       0       0x0        COMMIT  0
e1554428 A---- e152aa88   0      0       0       0x0        COMMIT  0
e1554630 A---- e152afc0   0      0       0       0x0        COMMIT  0
e1554838 A---- e152b4f8   0      0       0       0x0        COMMIT  0
e1554a40 A---- e152ba30   0      0       0       0x0        COMMIT  0
e1554c48 A---- e152bf68   0      0       0       0x0        COMMIT  0
e1554e50 A---- e152c4a0   0      0       0       0x0        COMMIT  0
e1555058 A---- e152c9d8   0      0       0       0x0        COMMIT  0
e1555260 A---- e152cf10   0      0       0       0x0        COMMIT  0
e1555468 A---- e152d448   0      0       0       0x0        COMMIT  0
e1555878 A---- e152e3f0   0      0       0       0x0        COMMIT  0
e1555a80 A-R-- e152deb8   41754  49      52      0x1daf658  COMMIT  0
e1555c88 A---- e152e928   0      0       0       0x0        COMMIT  0
 14 active, 128 total, 15 maximum concurrent

Hier ist auch genau der Punkt, wo man ansetzen kann, um die Dauer für den Rollback anzuschätzen: "curlog" muss wieder "beginlg" erreichen, dann ist der Rollback abgeschlossen. Die Dauer für den Rollback eines Logfiles lässt sich mitstoppen, und dann auf die Anzahl der noch zu verarbeitetenden Logfiles hochrechnen. Man erhält allerdings nur einen groben Richtwert.

Um gar nicht erst in diesen Punkt hineinzulaufen, dass lange Transaktionen abbrechen oder sogar der Server für einen Rollback geblocked wird, bieten sich folgende Möglichkeiten an:

  • Weitere Logical Logfiles hinzufügen.
  • Transaktionen vorher in einem gleichwertigen Testsystem testen.
  • Transaktionen verkleinern, und in "Häppchen" ausführen.
  • Datenbank sichern, aus dem Logging nehmen, gewünschte Operationen ausführen, Logging wieder einschalten.
  • Verwendung von Raw Tables (Tabellen ohne Logging). Ist mit Vorsicht zu genießen, weil es keine Möglichkeit des Rollback gibt.
  • LTXHWM und LTXEHWM vergrößern. Ist jedoch nur dann zu empfehlen, wenn mit DYNAMIC_LOGS gearbeitet wird, da sonst die Gefahr besteht, dass das System keinen Protokollierplatz mehr zur Verfügung hat und hängen bleibt. Setzt man LTXHWM und LTXEHWM auf 100, werden lange Transaktionen niemals abgebrochen, und der Datenbankserver allokiert munter weitere Logical Logfiles nach. Sinnvoller ist es daher eventuell, wenn man LTXHWM auf einen Wert unter 100 setzt, und LTXEHWM auf 100. Transaktionen werden dann bei erreichen der LTXHWM abgebrochen, der Server aber nie beim Rollback blockiert, weil er durch das Nachallokieren von Logical Logfiles immer hinreichend Protokollierplatz zur Verfügung stehen hat.
  • Bei eingeschaltetem Feature DYNAMIC_LOGS: Weitere Logical Logfiles hinzufügen, LTXHWM von 70 (Default) auf 50 verringern, und LTXEHWM auf 100 setzen. Der Server kommt somit vermutlich kaum in die Verlegenheit, dass er Logical Logfiles nachallokieren muss, läuft aber auch nicht in die Gefahr, dass er durch Erreichen von LTXEHWM geblocked wird.

Was man jedoch immer bedenken muss: Auch in einer Datenbank ohne Logging werden DDL-Statements wie "create table", "alter table", "create index" etc. geloggt. Hier gibt es nur die Möglichkeit, mit mehr Logspace bzw. mit höheren Werten für LTXHWM / LTXEHWM zu kontern.

Tipp:
Häufig möchte man nur einzelnen Aktionen erlauben, dass sie viel Logspace benutzen dürfen. "Normale" Sessions sollen viel früher in die LTXHWM laufen. Ich habe bei IBM einen Feature Request eingereicht, um dieses in zukünftigen Informix-Versionen zu ermöglichen.