iSCSI SAN+Qlogic HBA+Linux crasht

[arnova]

We hebben hier een Transtec Provigo 510 iSCSI SAN (rebranded Promise Vtrak) deze hangt aan een Qlogic iSCSI HBA controller welke in een bak zit met Debian Etch x86 erop. Ik heb hier wel een eigen vanilla kernel (2.6.25) opgekwakt aangezien anders zowel mijn Qlogic iSCSI controller als mijn onboard intel ethernet controllers niet herkend worden. Ik heb in de Qlogic bios netjes alles ingesteld zodat ik onder Linux een /dev/sdc device krijg. Mijn /dev/sdc device is ca. 9TByte en omdat ik initieel wat met Ext3 wilde experimenteren (en ext3 maar max 8TByte aankan) heb ik met parted een GPT disklabel/partitie gemaakt waarbij ik 2 primaire 4.5 TByte partities heb.Tot dusver alles goed. Totdat ik een op 1 van de partities een ext3 filesysteem ga maken (met mke2fs -j /dev/sdc1), wanneer mke2fs bijna klaar is loopt mijn kernel log vol met:

code:

...
Jun 19 20:04:10 data03 kernel: qla4xxx 0000:08:01.1: scsi2:0:0:0: DEVICE RESET ISSUED.
Jun 19 20:04:10 data03 kernel: qla4xxx 0000:08:01.1: scsi(2:0:0:0): DEVICE RESET SUCCEEDED.
Jun 19 20:04:40 data03 kernel: qla4xxx 0000:08:01.1: scsi2:0:0:0: DEVICE RESET ISSUED.
Jun 19 20:04:40 data03 kernel: qla4xxx 0000:08:01.1: scsi(2:0:0:0): DEVICE RESET SUCCEEDED.
Jun 19 20:05:10 data03 kernel: qla4xxx 0000:08:01.1: scsi2:0:0:0: DEVICE RESET ISSUED.
Jun 19 20:05:10 data03 kernel: qla4xxx 0000:08:01.1: scsi(2:0:0:0): DEVICE RESET SUCCEEDED.
...

Ik heb geprobeerd met dd te reproduceren (dd if=/dev/zero of=/dev/sdc1 bs=1M), om zo te proberen uit te vogelen waar het probleem precies zit. Echter zonder resultaat. Badblocks wil zo ie zo niet werken want die vind 4.5TByte te groot.

Iemand wellicht nog suggesties/ideeen om dit probleem te tackelen?

[deadinspace]

arnova schreef op maandag 23 juni 2008 @ 19:43:
Ik heb hier wel een eigen vanilla kernel (2.6.25) opgekwakt aangezien anders zowel mijn Qlogic iSCSI controller als mijn onboard intel ethernet controllers niet herkend worden.

Merk op dat vanilla kernels relatief weinig QA testing krijgen en je dus het risico loopt dat er verassingen in zitten (zoals een brakke qla4xxx driver bijvoorbeeld ).

Mijn /dev/sdc device is ca. 9TByte en omdat ik initieel wat met Ext3 wilde experimenteren (en ext3 maar max 8TByte aankan) [...]

Ext3 kan tot 16TB als ik me niet vergis (met 4KB block size).

Totdat ik een op 1 van de partities een ext3 filesysteem ga maken (met mke2fs -j /dev/sdc1), wanneer mke2fs bijna klaar is loopt mijn kernel log vol met [device resets]

• Is het reproduceerbaar? Als je nog eens mke2fst, krijg je dan hetzelfde probleem? Op dezelfde plaats?
• Wat gebeurt er verder precies? In je topictitel zeg je "crasht", maar loopt echt de hele machine vast, of gebeurt er iets anders?
• Wat is "bijna klaar"? Waar is mke2fs mee bezig op het moment dat het mis gaat?
• unload en re-load qla4xxx eens met de ql4xextended_error_logging optie. Geeft dat interessante gegevens in je log als je nog eens mk2fst?

Ik heb geprobeerd met dd te reproduceren (dd if=/dev/zero of=/dev/sdc1 bs=1M), om zo te proberen uit te vogelen waar het probleem precies zit. Echter zonder resultaat.

Heb je dat laten lopen tot de partitie vol was? Met 4.5TB zal dat best wel even duren namelijk, een uur of 10?

[arnova]

deadinspace schreef op maandag 23 juni 2008 @ 20:17:
[...]

Merk op dat vanilla kernels relatief weinig QA testing krijgen en je dus het risico loopt dat er verassingen in zitten (zoals een brakke qla4xxx driver bijvoorbeeld ).

[...]

Ext3 kan tot 16TB als ik me niet vergis (met 4KB block size).

[...]

• Is het reproduceerbaar? Als je nog eens mke2fst, krijg je dan hetzelfde probleem? Op dezelfde plaats?
• Wat gebeurt er verder precies? In je topictitel zeg je "crasht", maar loopt echt de hele machine vast, of gebeurt er iets anders?
• Wat is "bijna klaar"? Waar is mke2fs mee bezig op het moment dat het mis gaat?
• unload en re-load qla4xxx eens met de ql4xextended_error_logging optie. Geeft dat interessante gegevens in je log als je nog eens mk2fst?

[...]

Heb je dat laten lopen tot de partitie vol was? Met 4.5TB zal dat best wel even duren namelijk, een uur of 10?

Inmiddels nog wat meer getest:
- kernel 2.6.24 heeft hetzelfde probleem, zowel 32bit als 64bit;
- een totaal andere bak gebruiken met open-iscsi + standaard ethernet controller geeft met deze SAN hetzelfde probleem! -> Conclusie zit iig niet in de Qlogic iSCSI controller;
- het probleem is redelijk reproduceerbaar. Ook met een kleinere partitie op de SAN (bv. 1TByte) loopt aan het einde van mke2fs de boel de soep in;
- Tevens op de 1 TByte partitie geprobeert met "dd" de hele partitie te lezen en te schrijven en dit geeft geen problemen;
- aanzetten van de qla4xxx debug optie geeft geen extra info, helaas.
- de laatste versie e2fsprogs (en dus mke2fs) lost het probleem ook niet op.

Extra info:
- De plek waar mke2fs de soep in loopt is wanneer hij zegt "Writing superblocks and filesystem accounting information:";
- ext3 krijg je met standaard settings onder zowel 32bit als 64bit x86 echt maar tot max. 8TByte. Volgens mij kan 16TByte alleen op platformen als Alpha werken ivm. de pagesize...
- Wanneer het probleem zich voordoet is de SAN zowel op de iSCSI port, RS232 port en management ethernet port NIET meer te bereiken. Deze moet je een power-cycle geven om er weer bij te kunnen. Je server blijft het verder wel doen maar uiteraard is het scsi device niet meer te benaderen...

Conclusie tot dusver: Vreemd genoeg lijkt het een combinatie van de SAN en mke2fs/ext3 te zijn. Maar aangezien ik er 2 heb en beide hetzelfde probleem hebben zal er niet echt iets "stuk" zijn in de SAN. Ik denk dat de volgende stap is het tweaken van wat settings op SAN....

[deadinspace]

arnova schreef op dinsdag 24 juni 2008 @ 19:52:
De plek waar mke2fs de soep in loopt is wanneer hij zegt "Writing superblocks and filesystem accounting information:";

Hmm, dan wil ik wel eens een strace van mke2fs zien:

strace -tt -o mke2fs.log mke2fs -j /dev/sdc1

Die logfile zou goed te groot kunnen zijn om hier te posten. In dat geval is vooral het laatste stuk interessant. In ieder geval alles vanaf de regel die "Writing superblocks" bevat, en het liefst ook een stukje ervoor.

Ik neem aan dat mke2fs vanaf dat moment geen voortgang meer boekt trouwens?

ext3 krijg je met standaard settings onder zowel 32bit als 64bit x86 echt maar tot max. 8TByte. Volgens mij kan 16TByte alleen op platformen als Alpha werken ivm. de pagesize...

Uit Documentation/filesystems/ext2.txt:

code:

Filesystem block size:     1kB        2kB        4kB        8kB

File size limit:          16GB      256GB     2048GB     2048GB
Filesystem size limit:  2047GB     8192GB    16384GB    32768GB

16TB met 4KB blocks dus, wat wel zo'n beetje standaard is.

Ext2/3 kan 32TB aan met 8KB blocks, maar dat werkt inderdaad alleen op architecturen die 8KB pages ondersteunen (en alpha is daar een van).

Wanneer het probleem zich voordoet is de SAN zowel op de iSCSI port, RS232 port en management ethernet port NIET meer te bereiken. Deze moet je een power-cycle geven om er weer bij te kunnen.

Wel raar dat die SAN zo over de zeik raakt, zeker als dat ook gewoon over ethernet lukt. In een test hier doet mke2fs alleen seeken, schrijven, en syncen. Niets daarvan zou een SAN mogen crashen lijkt mij.

[Kippenijzer]

MAar als de SAN zo over de zeik gaat is het dan niet gewoon een idee om de leverancier te bellen en deze het probleem voor te leggen / uit te laten zoeken, ik neem aan dat ze 'algehele' compatibiliteit claimen te bieden, wat ze blijkbaar niet doen, zonde daar je eigen tijd in te steken, zeker als het waarschijnlijk is dat meer mensen hier last van hebben/zullen krijgen.

[arnova]

deadinspace schreef op dinsdag 24 juni 2008 @ 21:18:
[...]

Hmm, dan wil ik wel eens een strace van mke2fs zien:

strace -tt -o mke2fs.log mke2fs -j /dev/sdc1

Die logfile zou goed te groot kunnen zijn om hier te posten. In dat geval is vooral het laatste stuk interessant. In ieder geval alles vanaf de regel die "Writing superblocks" bevat, en het liefst ook een stukje ervoor.

Ik neem aan dat mke2fs vanaf dat moment geen voortgang meer boekt trouwens?

[...]

Uit Documentation/filesystems/ext2.txt:

code:

Filesystem block size:     1kB        2kB        4kB        8kB

File size limit:          16GB      256GB     2048GB     2048GB
Filesystem size limit:  2047GB     8192GB    16384GB    32768GB

16TB met 4KB blocks dus, wat wel zo'n beetje standaard is.

Ext2/3 kan 32TB aan met 8KB blocks, maar dat werkt inderdaad alleen op architecturen die 8KB pages ondersteunen (en alpha is daar een van).

[...]

Wel raar dat die SAN zo over de zeik raakt, zeker als dat ook gewoon over ethernet lukt. In een test hier doet mke2fs alleen seeken, schrijven, en syncen. Niets daarvan zou een SAN mogen crashen lijkt mij.

Het rare is dat, al is het traag, mke2fs uiteindelijk wel "eindigt" zonder een foutmelding of segfault. Die strace heb ik nog niet gedaan, maar inmiddels heb ik wel uitgevogeld dat het probleem weg is wanneer ik de write cache (write back) op san uit zet (write thru). Inmiddels ook contact gehad met de leverancier en die hebben een case aangemaakt voor het probleem. Het lijkt mij toch dat er meer mensen zijn die die San icm. Linux gebruiken en dus ook tegen dit problem aan zouden moeten lopen. Aangezien de performance penalty met write cache uit aanzienlijk is, moeten ze dit toch echt oplossen...

[deadinspace]

arnova schreef op woensdag 25 juni 2008 @ 20:45:
Het rare is dat, al is het traag, mke2fs uiteindelijk wel "eindigt" zonder een foutmelding of segfault. Die strace heb ik nog niet gedaan, maar inmiddels heb ik wel uitgevogeld dat het probleem weg is wanneer ik de write cache (write back) op san uit zet (write thru).

Hmm, in dat geval vermoed ik dat het syncen van mke2fs dit veroorzaakt. Het is goed mogelijk dat sync() ook een opdracht naar het SAN stuurt om alle gebufferde data naar de schijven te commiten, en dat het SAN dat dus heel braaf gaat doen, en ondertussen zo ongeveer nergens meer op reageert.

Een strace van mke2fs zou daar nog steeds meer duidelijkheid over kunnen geven, maar misschien dat het volgende ook interessant is:

dd if=/dev/zero of=/dev/sdc1 bs=1M count=8192; echo 'Syncing...'; sync

Als je dat uitvoert, en je komt bij het "Syncing..." gedeelte, lijkt het SAN dan ook vast te slaan?

Het zou kunnen dat dit nergens op reageren van het SAN de reden is dat je iSCSI controller (of de driver) resets gaat issuen, maar dat is wel heel erg gissen zonder verder onderzoek.

Ik neem trouwens aan dat als mke2fs uiteindelijk klaar is, het SAN weer normaal reageert?

[arnova]

deadinspace schreef op donderdag 26 juni 2008 @ 00:19:
[...]

Hmm, in dat geval vermoed ik dat het syncen van mke2fs dit veroorzaakt. Het is goed mogelijk dat sync() ook een opdracht naar het SAN stuurt om alle gebufferde data naar de schijven te commiten, en dat het SAN dat dus heel braaf gaat doen, en ondertussen zo ongeveer nergens meer op reageert.

Een strace van mke2fs zou daar nog steeds meer duidelijkheid over kunnen geven, maar misschien dat het volgende ook interessant is:

dd if=/dev/zero of=/dev/sdc1 bs=1M count=8192; echo 'Syncing...'; sync

Als je dat uitvoert, en je komt bij het "Syncing..." gedeelte, lijkt het SAN dan ook vast te slaan?

Het zou kunnen dat dit nergens op reageren van het SAN de reden is dat je iSCSI controller (of de driver) resets gaat issuen, maar dat is wel heel erg gissen zonder verder onderzoek.

Ik neem trouwens aan dat als mke2fs uiteindelijk klaar is, het SAN weer normaal reageert?

Ik vermoede ook al dat het iets met de sync van mke2fs te maken had. De

dd if=/dev/zero of=/dev/sdc1 bs=1M count=8192; echo 'Syncing...'; sync

die je suggereerde, haalt overigens niks uit: het werkt gewoon cq. ik krijg het daarmee niet gereproduceerd.

De strace van mke2fs kan je hier vinden (let op: is wel 90mb!): http://www.eld.leidenuniv.../public/mke2fs-data04.log .Het rare is dat de ene keer de SAN echt helemaal niet meer reageert nadat mke2fs klaar is en pas weer tot leven komt na of een powercycle of nadat de watchdog dat ding een reset geeft. Andere keren blijft ie wel reageren, maar voelbaar trager.

Ik denk inderdaad ook dat de SCSI layer op de client op een gegeven moment een SCSI reset stuurt omdat de node niet (snel genoeg) reageert.

[deadinspace]

arnova schreef op donderdag 26 juni 2008 @ 13:01:
De strace van mke2fs kan je hier vinden (let op: is wel 90mb!): http://www.eld.leidenuniv.../public/mke2fs-data04.log

Die strace bevestigt mijn vermoeden wel redelijk:

code:

08:42:57.066428 _llseek(3, 999519424512, [999519424512], SEEK_SET) = 0
08:42:57.066459 write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
08:42:57.066514 fsync(3)                = 0
08:46:59.059229 lseek(3, 1024, SEEK_SET) = 1024
08:46:59.059274 write(3, "\0\300F\7LJ\215\16\267C"..., 1024) = 1024
08:46:59.059335 fsync(3)                = 0

Je mke2fs schrijft zo'n 15GB aan data weg (in ongeveer een half miljoen schrijfacties), en daarna fsync()t hij (de eerste fsync() in de paste). En die fsync() doet er zo'n 4 minuten over.

Als je SAN een schrijfsnelheid haalt van 60 MB/sec, dan kan hij 15GB wegschrijven in 4 minuten. Misschien buffert hij dus alle schrijfacties die mke2fs doet tot mke2fs fsync()t, wat het wel logisch maakt dat die stap lang duurt en dat het SAN op dat moment zwaar belast is, en dat dit niet optreedt als je hem op write through instelt. Hoe groot zijn zijn writeback caches?

Ik neem aan dat zowel die mke2fs onder strace als die dd opdracht zijn uitgevoerd met de cache op write back? Dat die dd opdracht het niet gereproduceerd krijgt kan misschien komen doordat dd naar een continue stuk (van 8GB) schreef, terwijl mke2fs juist erg verspreid schrijft (32KB hier, 32KB daar). Misschien heeft het SAN het een stuk moeilijker met dat tweede geval (het zal iig een stuk meer seeks veroorzaken op de disks).

Het rare is dat de ene keer de SAN echt helemaal niet meer reageert nadat mke2fs klaar is en pas weer tot leven komt na of een powercycle of nadat de watchdog dat ding een reset geeft. Andere keren blijft ie wel reageren, maar voelbaar trager.

De watchdog van het SAN zelf bedoel je dan neem ik aan, niet je SCSI kaart/driver?

Het zou ook nog kunnen dat het SAN er zelf wel uit zou komen, maar dat die SCSI resets hem net over de rand duwen ofzo. Misschien dat die resets helemaal uit te zetten zijn met de ql4xdontresethba optie van je driver.

[arnova]

deadinspace schreef op donderdag 26 juni 2008 @ 13:38:
[...]

Die strace bevestigt mijn vermoeden wel redelijk:

code:

08:42:57.066428 _llseek(3, 999519424512, [999519424512], SEEK_SET) = 0
08:42:57.066459 write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
08:42:57.066514 fsync(3)                = 0
08:46:59.059229 lseek(3, 1024, SEEK_SET) = 1024
08:46:59.059274 write(3, "\0\300F\7LJ\215\16\267C"..., 1024) = 1024
08:46:59.059335 fsync(3)                = 0

Je mke2fs schrijft zo'n 15GB aan data weg (in ongeveer een half miljoen schrijfacties), en daarna fsync()t hij (de eerste fsync() in de paste). En die fsync() doet er zo'n 4 minuten over.

Als je SAN een schrijfsnelheid haalt van 60 MB/sec, dan kan hij 15GB wegschrijven in 4 minuten. Misschien buffert hij dus alle schrijfacties die mke2fs doet tot mke2fs fsync()t, wat het wel logisch maakt dat die stap lang duurt en dat het SAN op dat moment zwaar belast is, en dat dit niet optreedt als je hem op write through instelt. Hoe groot zijn zijn writeback caches?

Ik neem aan dat zowel die mke2fs onder strace als die dd opdracht zijn uitgevoerd met de cache op write back? Dat die dd opdracht het niet gereproduceerd krijgt kan misschien komen doordat dd naar een continue stuk (van 8GB) schreef, terwijl mke2fs juist erg verspreid schrijft (32KB hier, 32KB daar). Misschien heeft het SAN het een stuk moeilijker met dat tweede geval (het zal iig een stuk meer seeks veroorzaken op de disks).

[...]

De watchdog van het SAN zelf bedoel je dan neem ik aan, niet je SCSI kaart/driver?

Het zou ook nog kunnen dat het SAN er zelf wel uit zou komen, maar dat die SCSI resets hem net over de rand duwen ofzo. Misschien dat die resets helemaal uit te zetten zijn met de ql4xdontresethba optie van je driver.

Mijn (shared) cache is 256Mb, als ik mij niet vergis. Zowel dd als mke2fs zijn idd met write cache (write back) aan uitgevoerd. Met de watchdog bedoel ik inderdaad die van de SAN zelf ja. Ik ga nog even de qla4xdontresethba optie proberen, al heb ik er een hard hoofd in dat dat wat gaat uitmaken. Ik vermoed toch dat het iets van een bug in de firmware van de SAN is cq. dat een hele hoge random I/O load niet aankan....

Nog ter info: De keren dat die SAN overigens echt helemaal dood is krijg in mijn kernel log het volgende:

code:

Jun 26 15:04:38 data04 kernel: qla4xxx 0000:08:01.1: scsi2:0:0:0: DEVICE RESET ISSUED.
Jun 26 15:04:38 data04 kernel: qla4xxx 0000:08:01.1: scsi(2:0:0:0): DEVICE RESET SUCCEEDED.
Jun 26 15:05:10 data04 kernel: qla4xxx 0000:08:01.1: scsi(2:0:0:0): ADAPTER RESET ISSUED.
Jun 26 15:05:39 data04 kernel: qla4xxx 0000:08:01.1: HOST RESET FAILED.
Jun 26 15:05:39 data04 kernel: sd 2:0:0:0: Device offlined - not ready after error recovery
Jun 26 15:05:39 data04 kernel: sd 2:0:0:0: Device offlined - not ready after error recovery
Jun 26 15:05:39 data04 kernel: sd 2:0:0:0: [sdc] Result: hostbyte=DID_OK driverbyte=DRIVER_TIMEOUT,SUGGEST_OK
Jun 26 15:05:39 data04 kernel: end_request: I/O error, dev sdc, sector 605552674
Jun 26 15:05:39 data04 kernel: Buffer I/O error on device sdc1, logical block 605552640
Jun 26 15:05:39 data04 kernel: lost page write due to I/O error on sdc1
Jun 26 15:05:39 data04 kernel: Buffer I/O error on device sdc1, logical block 605552641
Jun 26 15:05:39 data04 kernel: lost page write due to I/O error on sdc1
Jun 26 15:05:39 data04 kernel: Buffer I/O error on device sdc1, logical block 605552642
Jun 26 15:05:39 data04 kernel: lost page write due to I/O error on sdc1
Jun 26 15:05:39 data04 kernel: Buffer I/O error on device sdc1, logical block 605552643
Jun 26 15:05:39 data04 kernel: lost page write due to I/O error on sdc1
Jun 26 15:05:39 data04 kernel: Buffer I/O error on device sdc1, logical block 605552644
Jun 26 15:05:39 data04 kernel: : rejecting I/O to offline device
Jun 26 15:05:39 data04 kernel: sd 2:0:0:0: rejecting I/O to offline device
Jun 26 15:05:39 data04 last message repeated 343 times
Jun 26 15:05:39 data04 kernel: sd 2:0:0:0: [sdc] Result: hostbyte=DID_OK driverbyte=DRIVER_TIMEOUT,SUGGEST_OK
Jun 26 15:05:39 data04 kernel: end_request: I/O error, dev sdc, sector 601358370
Jun 26 15:05:39 data04 kernel: sd 2:0:0:0: rejecting I/O to offline device

[ Voor 32% gewijzigd door arnova op 26-06-2008 15:08 ]

[arnova]

Inmiddels geupdate firmware van Promise zelf geflashd in de SAN en mijn probleem is opgelost :-D Beetje jammer dat ze die dingen met zulke oude firmware (Aug-2007) hebben uitgeleverd, anders had ik dit probleem niet gehad....

[deadinspace]

arnova schreef op donderdag 03 juli 2008 @ 21:36:
Inmiddels geupdate firmware van Promise zelf geflashd in de SAN en mijn probleem is opgelost :-D Beetje jammer dat ze die dingen met zulke oude firmware (Aug-2007) hebben uitgeleverd, anders had ik dit probleem niet gehad....

Hmm, ik vind het eerder jammer dat ze die firmware überhaupt de deur uit gedaan hebben dan. Wat is dat voor een SAN? "Ojee, disk I/O! *sterf*"

Maargoed, fijn dat het is opgelost iig