mt -f /dev/nst0 asf X geeft soms I/O error

Pagina: 1
Acties:

Acties:
  • 0 Henk 'm!

  • bucovaina89
  • Registratie: Juli 2010
  • Laatst online: 29-04 20:53
Hoi,

Op verschillende Linux bakken, zowel Debian als CentOS heb ik het voor dat soms om onduidelijke redenen mt een I/O error geeft als ik file markers zoek op tape. Het lijkt me meer voor te komen naarmate de file marker count hoger oploopt, dus grotere kans bij file marker #8 dan file marker #2. Het probleem is meestal opgelost door de tape te ejecten en dan terug hetzelfde commando in te geven. De tape drive (Quantum LTO-8 internal SAS tape drive) waar ik het nu mee heb, is een jaar oud en hoop en al voor een terabyte aan data schrijven/lezen gebruikt.

Ik heb dit fenomeen voor gehad met verschillende tape drives gaande van HP LTO-3 tot LTO-5 en weet echt niet waarom dit gebeurt. De enige gok die ik kan doen is dat de drive voorbij een file marker leest en die daarna niet meer gevonden krijgt. Er is een timeout en de tape drive throwt dan een read error of zo. Tape eruit, tape er terug in and all was fine again 8)7 .

Goed de tape drives en cartridges die ik thuis gebruik (HP stuff LTO3-5) zijn allemaal 2dehands gebruikt, maar de Quantum is op het werk en die is nieuw, alsook de cartridge. Samen met het feit dat ik dit met haast alle drives heb voor gehad doet me niet vermoeden dat dit puur aan de drives ligt.

Heeft iemand hier ervaring mee?

Een stom voorbeeld van waar ik nu tegenaan loop. Ik ben verschillende tar archiven aan het restoren van een tape. Op elke file marker staat er een tar archief. De eerste keren gaat het goed maar tegen file marker 8 loop ik tegen een I/O error aan, wat ik dan ook doe, het loopt mis.

Wat ik soms merk is dat het mt -f asf X commando soms lang duurt, niettegenstaande dat de tape head op die moment vlak tegen de file marker zit omdat ik net een tar -xvf heb gedaan van de voorgaande file marker. Meestal gaat het wel bijna instant (wat ook te verwachten is)
code:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
mt -f /dev/nst0 rewind
mt -f /dev/nst0 asf 1 && tar -xvf /dev/nst0 
mt -f /dev/nst0 asf 2 && tar -xvf /dev/nst0 # hier ging de asf 2 bijv traag (tape gaat snel maar drive moet lang zoeken), maar de tape head staat voor het asf 2 commando op de laatste block van file marker 1 dus ik zou vermoeden dat dit haast instant zou moeten gaan.
mt -f /dev/nst0 asf 3 && tar -xvf /dev/nst0 
mt -f /dev/nst0 asf 4 && tar -xvf /dev/nst0 
mt -f /dev/nst0 asf 5  && tar -xvf /dev/nst0 
mt -f /dev/nst0 asf 6  && tar -xvf /dev/nst0 
mt -f /dev/nst0 asf 7  && tar -xvf /dev/nst0 
mt -f /dev/nst0 asf 8 SEEKING SEEKING SEEKING
mt I/O error
mt -f /dev/nst0 rewind
mt I/O error
mt -f /dev/nst0 asf 0
mt I/O error
mt -f /dev/nst0 eject
#tape er terug in
mt -f /dev/nst0 asf 8 # en nu faalt die niet


deze keer ging het dus bijvoorbeeld goed. Het 2de commando (fsf) ging haast instant wat ook te verwachten is omdat de tape head ervoor op de laatste block van file marker 8 stond, maar soms gaat dit dus niet :)
code:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
[root@tapews btrfs]# mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=8, block number=639866, partition=1.
Tape block size 0 bytes. Density code 0x5e (no translation).
Soft error count since last status=0
General status bits on (1010000):
 ONLINE IM_REP_EN
[root@tapews btrfs]# mt -f /dev/nst0 fsf 1
[root@tapews btrfs]# mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=9, block number=0, partition=1.
Tape block size 0 bytes. Density code 0x5e (no translation).
Soft error count since last status=0
General status bits on (81010000):
 EOF ONLINE IM_REP_EN
[root@tapews btrfs]#


En nog een aanvulling, bij de eerste keer dat ik 2010-05-30.tar.gz probeerde te extracten van tape ging het mis op 79GB, nu is hij nog bezig maar gaat hij daar weer vlotjes overheen. Het is dus niet alleen met file markers zoeken dat hij het heeft, maar dus ook bij data lezen van tape.
code:
1
2
3
4
5
6
7
8
9
10
-rw-r--r-- 1 root root 103G Apr 30 11:14 2007-12-02.tar.gz
-rw-r--r-- 1 root root 114G Apr 30 13:37 2008-03-23.tar.gz
-rw-r--r-- 1 root root 123G Apr 30 16:21 2008-06-01.tar.gz
-rw-r--r-- 1 root root 129G Apr 30 19:18 2008-08-31.tar.gz
-rw-r--r-- 1 root root 137G Apr 30 23:19 2008-11-30.tar.gz
-rw------- 1 root root 144G May  4 16:40 2009-05-17.tar.gz
-rw-r--r-- 1 root root 194G May  1 09:30 2009-05-31.tar.gz
-rw------- 1 root root 192G May  4 20:26 2009-11-29.tar.gz
-rw-r--r-- 1 root root 311G May  2 04:53 2010-02-28.tar.gz
-rw------- 1 root root 179G May  5 13:36 2010-05-30.tar.gz



En nog een toevoeging, dit geeft me dan precies toch de indruk dat de tape drive moeite heeft om de cassette te lezen ... Deze berichten zie ik in de kernel ring buffer. Ditmaal is hij er wel door geraakt.
code:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
[Wed May  5 13:06:15 2021]  [<ffffffff9ad80ddd>] wait_for_completion+0xfd/0x140
[Wed May  5 13:06:15 2021]  [<ffffffff9a6db4d0>] ? wake_up_state+0x20/0x20
[Wed May  5 13:06:15 2021]  [<ffffffffc1cd6a87>] st_do_scsi.constprop.23+0x297/0x420 [st]
[Wed May  5 13:06:15 2021]  [<ffffffffc1cdb83d>] st_read+0x32d/0xda0 [st]
[Wed May  5 13:06:15 2021]  [<ffffffff9a9045ae>] ? security_file_permission+0x3e/0xa0
[Wed May  5 13:06:15 2021]  [<ffffffff9a84a6df>] vfs_read+0x9f/0x170
[Wed May  5 13:06:15 2021]  [<ffffffff9a84b59f>] SyS_read+0x7f/0xf0
[Wed May  5 13:06:15 2021]  [<ffffffff9ad8dede>] system_call_fastpath+0x25/0x2a
[Wed May  5 13:50:09 2021] INFO: task tar:4053 blocked for more than 120 seconds.
[Wed May  5 13:50:09 2021] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Wed May  5 13:50:09 2021] tar             D ffff9e878d09ac80     0  4053   3366 0x00000080
[Wed May  5 13:50:09 2021] Call Trace:
[Wed May  5 13:50:09 2021]  [<ffffffff9ad80a29>] schedule+0x29/0x70
[Wed May  5 13:50:09 2021]  [<ffffffff9ad7e531>] schedule_timeout+0x221/0x2d0
[Wed May  5 13:50:09 2021]  [<ffffffff9aadeb10>] ? scsi_dispatch_cmd+0xb0/0x240
[Wed May  5 13:50:09 2021]  [<ffffffff9aae7cf8>] ? scsi_request_fn+0x48/0x680
[Wed May  5 13:50:09 2021]  [<ffffffff9ad80ddd>] wait_for_completion+0xfd/0x140
[Wed May  5 13:50:09 2021]  [<ffffffff9a6db4d0>] ? wake_up_state+0x20/0x20
[Wed May  5 13:50:09 2021]  [<ffffffffc1cd6a87>] st_do_scsi.constprop.23+0x297/0x420 [st]
[Wed May  5 13:50:09 2021]  [<ffffffffc1cdb83d>] st_read+0x32d/0xda0 [st]
[Wed May  5 13:50:09 2021]  [<ffffffff9a904539>] ? security_inode_setsecurity+0x19/0x30
[Wed May  5 13:50:09 2021]  [<ffffffff9a84a6df>] vfs_read+0x9f/0x170
[Wed May  5 13:50:09 2021]  [<ffffffff9a84b59f>] SyS_read+0x7f/0xf0
[Wed May  5 13:50:09 2021]  [<ffffffff9ad8dede>] system_call_fastpath+0x25/0x2a
[Wed May  5 13:52:09 2021] INFO: task tar:4053 blocked for more than 120 seconds.
[Wed May  5 13:52:09 2021] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Wed May  5 13:52:09 2021] tar             D ffff9e878d09ac80     0  4053   3366 0x00000080
[Wed May  5 13:52:09 2021] Call Trace:
[Wed May  5 13:52:09 2021]  [<ffffffff9ad80a29>] schedule+0x29/0x70
[Wed May  5 13:52:09 2021]  [<ffffffff9ad7e531>] schedule_timeout+0x221/0x2d0
[Wed May  5 13:52:09 2021]  [<ffffffff9aadeb10>] ? scsi_dispatch_cmd+0xb0/0x240
[Wed May  5 13:52:09 2021]  [<ffffffff9aae7cf8>] ? scsi_request_fn+0x48/0x680
[Wed May  5 13:52:09 2021]  [<ffffffff9ad80ddd>] wait_for_completion+0xfd/0x140
[Wed May  5 13:52:09 2021]  [<ffffffff9a6db4d0>] ? wake_up_state+0x20/0x20
[Wed May  5 13:52:09 2021]  [<ffffffffc1cd6a87>] st_do_scsi.constprop.23+0x297/0x420 [st]
[Wed May  5 13:52:09 2021]  [<ffffffffc1cdb83d>] st_read+0x32d/0xda0 [st]
[Wed May  5 13:52:09 2021]  [<ffffffff9a904539>] ? security_inode_setsecurity+0x19/0x30
[Wed May  5 13:52:09 2021]  [<ffffffff9a84a6df>] vfs_read+0x9f/0x170
[Wed May  5 13:52:09 2021]  [<ffffffff9a84b59f>] SyS_read+0x7f/0xf0
[Wed May  5 13:52:09 2021]  [<ffffffff9ad8dede>] system_call_fastpath+0x25/0x2a
[Wed May  5 13:54:08 2021] INFO: task tar:4053 blocked for more than 120 seconds.
[Wed May  5 13:54:08 2021] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Wed May  5 13:54:08 2021] tar             D ffff9e878d09ac80     0  4053   3366 0x00000080
[Wed May  5 13:54:08 2021] Call Trace:
[Wed May  5 13:54:08 2021]  [<ffffffff9ad80a29>] schedule+0x29/0x70
[Wed May  5 13:54:08 2021]  [<ffffffff9ad7e531>] schedule_timeout+0x221/0x2d0
[Wed May  5 13:54:08 2021]  [<ffffffff9aadeb10>] ? scsi_dispatch_cmd+0xb0/0x240
[Wed May  5 13:54:08 2021]  [<ffffffff9aae7cf8>] ? scsi_request_fn+0x48/0x680
[Wed May  5 13:54:08 2021]  [<ffffffff9ad80ddd>] wait_for_completion+0xfd/0x140
[Wed May  5 13:54:08 2021]  [<ffffffff9a6db4d0>] ? wake_up_state+0x20/0x20
[Wed May  5 13:54:08 2021]  [<ffffffffc1cd6a87>] st_do_scsi.constprop.23+0x297/0x420 [st]
[Wed May  5 13:54:08 2021]  [<ffffffffc1cdb83d>] st_read+0x32d/0xda0 [st]
[Wed May  5 13:54:08 2021]  [<ffffffff9a904539>] ? security_inode_setsecurity+0x19/0x30
[Wed May  5 13:54:08 2021]  [<ffffffff9a84a6df>] vfs_read+0x9f/0x170
[Wed May  5 13:54:08 2021]  [<ffffffff9a84b59f>] SyS_read+0x7f/0xf0
[Wed May  5 13:54:08 2021]  [<ffffffff9ad8dede>] system_call_fastpath+0x25/0x2a


Ik denk dat ik een idee heb waarom:
Afbeeldingslocatie: https://tweakers.net/i/TXrTxEvobHe_8DIqjHiABowKGh4=/800x/filters:strip_exif()/f/image/EqzU0zu5pUp0tg4ztq45oKAW.png?f=fotoalbum_large

[ Voor 60% gewijzigd door bucovaina89 op 05-05-2021 14:48 ]