Säilytys olla voi valoisampaa
Tämä teksti on osa blogisarjaamme, jossa yksittäiset henkilöt kirjoittavat sekalaisista pitkäaikaissäilytysteemoista vapaamuotoisesti. Blogisarjaamme ei ole tarkoitettu ohjaaviksi säännöiksi tai ohjeiksi, vaan inspiraatioksi ideoille ja keskustelulle.
Always look on the bright side of file. Törmäsimme vastikään tuotannossa siirtopakettiin, jonka validointi aikakatkaistiin. Paketti ei ollut erityisen suuri ja sisälsi DPX-kuvia, joita olemme vastaanottaneet vuosia ilman ongelmia. Paketin tutkimisen yhteydessä meille huomautettiin, että tummasävyisten kuvien käsittely on viisisataa kertaa kirkkaita kuvia nopeampaa.
Tässä blogikirjoituksessa syväluotaamme tapauksen teknisiin yksityiskohtiin. Aloitamme profiloimalla koodin suoritusta, selvitämme hitauden juurisyyn ja viimeiseksi korjaamme sen.
Kuvien kirkkauden varmastikin täytyy olla harhauttava savusilli?
Virheen toistaminen
Saimme tutkittavaksemme yhden tumman ja yhden kirkkaan DPX-kuvan. Kirkkaan kuvan käsittely oli todella 500 kertaa tummaa kuvaa hitaampaa. Alkuperäisten kuvien sijaan olemme luoneet kaksi uutta kuvaa toistamaan saman virheen: tumma.dpx ja kirkas.dpx. Molemmat kuvat on luotu GIMP-työkalulla ja muunnettu ffmpeg-työkalulla DPX-formaattiin. Tumma.dpx on 3840x2160 kanvaasi täytettynä värillä 0x000414 ja kirkas.dpx on tämän negatiivi eli sama kanvaasi täynnä väriä 0xfffbeb.
Voimme toistaa virheen purkamalla kuvat:
# Pura $ gunzip *.gz # Tarkista formaatti $ file *.dpx kirkas.dpx: DPX image data, little-endian, 3840x2160, left to right/top to bottom tumma.dpx: DPX image data, little-endian, 3840x2160, left to right/top to bottom # Laske tarkistussummat $ sha256sum *.dpx 3169f1e6807efe3123c01dd16be7d2c0c8549c1567c879e02bcc02f1f273be36 kirkas.dpx 98b209794a6abf8c45065e462e28978f639fe2ca584a896f496c40e0556067ca tumma.dpx
ja ajamalla ne file-scraper -työkalun läpi:
$ for file in kirkas.dpx tumma.dpx time scraper scrape-file $file > /dev/null end ________________________________________________________ Executed in 125.82 secs fish external usr time 124.99 secs 0.00 micros 124.99 secs sys time 0.19 secs 875.00 micros 0.19 secs ________________________________________________________ Executed in 558.48 millis fish external usr time 381.17 millis 0.00 micros 381.17 millis sys time 185.60 millis 508.00 micros 185.09 millis
Kirkkaan kuvan validoinnissa kuluu kaksi minuuttia ja tumman kuvan validoinnissa puoli sekuntia. Ainoa ero kuvissa on kanvaasin väri.
Python koodin profilointi
File-scraper -työkalu suorittaa taustalla lukuisia eri työkaluja. Hitaan työkalun voi löytää manuaalisesti tutkimalla koodia ja suorittamalla komentoja. Python standardikirjastosta löytyy myös työkaluja, jotka automatisoivat tämän tehtävän. Ohjelmiston suorituskyvyn tutkiminen tunnetaan profilointina ja se onnistuu esimerkiksi cProfile-kirjastolla.
Lähdetään liikkeelle ajamalla kirkas kuva cProfile-kirjaston läpi ja järjestämällä tuloste kumulatiivisen suoritusajan mukaan:
$ python3 -m cProfile -s cumtime /usr/bin/scraper scrape-file kirkas.dpx | head -50 . . <scraper output> . 881009 function calls (860708 primitive calls) in 140.657 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 305/1 0.000 0.000 140.657 140.657 {built-in method builtins.exec} 1 0.000 0.000 140.657 140.657 scraper:3(<module>) 1 0.000 0.000 140.340 140.340 core.py:1126(__call__) 1 0.000 0.000 140.340 140.340 core.py:981(main) 1 0.000 0.000 140.340 140.340 core.py:1625(invoke) 2 0.000 0.000 140.339 70.170 core.py:1384(invoke) 2 0.000 0.000 140.339 70.170 core.py:703(invoke) 1 0.000 0.000 140.339 140.339 cmdline.py:45(scrape_file) 1 0.000 0.000 140.338 140.338 scraper.py:285(scrape) 1 0.000 0.000 140.335 140.335 scraper.py:140(detect_filetype) 7 0.000 0.000 140.334 20.048 scraper.py:464(_update_filetype) 1 0.000 0.000 140.312 140.312 detectors.py:182(detect) 1 0.000 0.000 140.263 140.263 detectors.py:100(identify) 1 0.000 0.000 140.263 140.263 fido.py:340(identify_file) 1 0.003 0.003 140.262 140.262 fido.py:665(match_formats) 40 0.000 0.000 140.107 3.503 re.py:198(search) 56 140.097 2.502 140.097 2.502 {method 'search' of 're.Pattern' objects} 360/3 0.001 0.000 0.323 0.108 <frozen importlib._bootstrap>:1002(_find_and_load) 354/2 0.001 0.000 0.323 0.161 <frozen importlib._bootstrap>:967(_find_and_load_unlocked) 464/3 0.000 0.000 0.322 0.107 <frozen importlib._bootstrap>:220(_call_with_frames_removed) 340/3 0.001 0.000 0.322 0.107 <frozen importlib._bootstrap>:659(_load_unlocked) 303/3 0.001 0.000 0.322 0.107 <frozen importlib._bootstrap_external>:844(exec_module) 1 0.000 0.000 0.316 0.316 cmdline.py:1(<module>) 1 0.000 0.000 0.270 0.270 scraper.py:1(<module>) 94/61 0.000 0.000 0.251 0.004 {built-in method builtins.__import__} 1 0.000 0.000 0.245 0.245 iterator.py:1(<module>) 112/46 0.000 0.000 0.238 0.005 <frozen importlib._bootstrap>:1033(_handle_fromlist) 1 0.000 0.000 0.195 0.195 wand_extractor.py:1(<module>) 1668 0.005 0.000 0.190 0.000 re.py:289(_compile) 1 0.000 0.000 0.188 0.188 image.py:1(<module>)
Etsimme tulosteesta kohtaa missä näemme selvän erotuksen kumulatiivisessa suoritusajassa (cumtime). Tässä tapauksessa huomaamme harvinaisen selkeästi lähes kaiken ajan kuluvan säännöllisten lausekkeiden tulkintaan Pythonin re-kirjastossa. Kumulatiivisen suoritusajan mukaisessa järjestyksessä voimme myös seurata ketjua ylöspäin ja nähdä, että metodien kutsumajärjestys on käytännössä:
scraper -> detectors -> fido -> re
FIDO-työkalun analysointi
FIDO-työkalu toimii etsimällä tiedostoista PRONOM-rekisterissä määriteltyjä tunnisteita (eng. signatures). Tunnisteet ovat säännöllisiä lausekkeita, jotka etsivät tiedostomuodoista niille tyypillisiä piirteitä. Esimerkiksi DPX-kuvien tapauksessa PRONOM määrittelee:
Description Magic number in first four bytes: XPDS indicates little-endian
byte order; 4 byte offset to image; Version 1.0
Position type Absolute from BOF
Offset 0
Maximum Offset 0
Byte order
Value 58504453{4}56312E30
Tämä tarkoittaa, että kaikki version 1.0 little-endian (nouseva tavujärjestys) DPX-kuvatiedostot alkavat kaavan 58504453{4}56312E30 mukaisesti.
- 58504453: Tarkat neljä tavua (XPDS)
- {4}: Mielivaltaiset neljä tavua
- 56312E30: Tarkat neljä tavua (v1.0)
Voimme verrata tätä DPX-kuviimme ja näemme niiden seuraavan samaa kaavaa:
$ xxd kirkas.dpx | head -1 00000000: 5850 4453 8006 0000 5631 2e30 0000 0000 XPDS....V1.0....
FIDO etsii tiedostoista juuri näitä tunnisteita. Voimme muokata FIDO-lähdekoodia pitämään kirjaa jokaisen tunnisteen etsimisen suoritusnopeudesta. Tämä onnistuu seuraavilla muutoksilla FIDO v1.6.1 lähdekoodiin:
diff --git a/fido/fido.py b/fido/fido.py index 3b5bc60..e1a337d 100755 --- a/fido/fido.py +++ b/fido/fido.py @@ -693,11 +693,14 @@ class Fido: """ self.current_count += 1 result = [] + times = [] + import time for format in self.formats: try: self.current_format = format if self.as_good_as_any(format, result): for sig in self.get_signatures(format): + time_start = time.time() self.current_sig = sig success = True for pat in self.get_patterns(sig): @@ -723,6 +726,8 @@ class Fido: break if success: result.append((format, sig.findtext("name"))) + time_end = time.time() + times.append((sig, time_end-time_start)) except Exception as e: sys.stderr.write(str(e) + "\n") continue @@ -731,6 +736,10 @@ class Fido: # sys.stdout.write('***', self.get_puid(format), regex) result = [match for match in result if self.as_good_as_any(match[0], result)] + + for i in times: + print(f"{i[1]:.8f}\t{i[0].findtext('name')}") + return result def match_extensions(self, filename):
Suorittamalla ylläolevan koodin ja järjestämällä tulosteen löydämme kymmenen hitainta tiedostomuototunnistetta:
$ fido kirkas.dpx 2>/dev/null | sort -g | tail -10 0.00032163 Drawing Interchange File Format 1.2 0.00033593 Drawing Interchange File Format 2.2 0.00037837 Drawing Interchange File Format 1.0 0.00038409 Interlis transfer file 2.2 b 0.00039887 Interlis 2.3 Transfer File 2 0.00049639 BibTeX Database File 0.00053000 HFS 0.00067973 Apple Partition Map ISO 9660 Hybrid, sig n.1 0.00070667 Apple Partition Map ISO 9660 Hybrid, sig n.2 133.29057360 MPEG-1/2 Audio Layer 3
Käytännössä koko suoritusaika kuluu MP3-audiotiedoston tunnisteiden etsimiseen. Toistamalla saman tummalle kuvalle kahden minuutin sijaan samojen tunnisteiden etsimiseen kuluu 0.1 millisekuntia, mikä on noin miljoona kertaa tai kuusi kertaluokkaa nopeampaa.
$ fido tumma.dpx 2>/dev/null | grep 'MPEG-1/2' 0.00017285 MPEG-1/2 Audio Layer 3
Palapelin kasaaminen
Tässä vaiheessa nokkelimmat lukijat saattavat jo aavistaa mikä hitauden aiheuttaa. Olemme havainneet:
- Hitauden aiheuttavan FIDO-työkalun etsimät PRONOM-tunnisteet.
- MPEG-1/2 Audio Layer 3 -tunnisteen olevan ylivoimaisesti hitain etsiä: https://www.nationalarchives.gov.uk/pronom/fmt/134.
- Kuvan kirkkauden todellakin vaikuttavan ohjelmiston toimintaan, koska muuten identtinen tummempi kuva ei toista virhettä.
Tutkitaan seuraavaksi FIDO:n ensimmäisenä etsimää MP3-tunnistetta.
<signature> <name>MPEG-1 Audio Layer 3 with ID3v2 Tag</name> <note>Regularly-spaced frame headers should always be discoverable near EOF. An ID3v1 tag of up to 355 bytes may be present at EOF.</note> <pattern> <position>EOF</position> <pronom_pattern>FFFB[10:EB]{46-1439}FFFB[10:EB]{46-1439}FFFB[10:EB]{46-1439}FFFB[10:EB]{46-1439}FFFB[10:EB]{46-1439}FFFB[10:EB]{46-1439}FFFB[10:EB]{47-1795}</pronom_pattern> <regex>(?s)\xff\xfb[\x10-\xeb].{46,1439}\xff\xfb[\x10-\xeb].{46,1439}\xff\xfb[\x10-\xeb].{46,1439}\xff\xfb[\x10-\xeb].{46,1439}\xff\xfb[\x10-\xeb].{46,1439}\xff\xfb[\x10-\xeb].{46,1439}\xff\xfb[\x10-\xeb].{47,1795}\Z</regex> </pattern> <pattern> <position>BOF</position> <pronom_pattern>494433</pronom_pattern> <regex>(?s)\AID3</regex> </pattern> </signature>
Oleellinen osuus on regex-elementti, jota FIDO käyttää etsintään. Kyseinen säännöllinen lauseke etsii MP3-kehyksiä tiedoston lopusta. Yksittäinen tunnisteen etsimä kehys seuraa kaavaa:
fffb[10-eb].{46,1439}
- fffb: Tarkat kaksi tavua
- [10-eb]: Yksi mielivaltainen tavu 0x10 ja 0xeb väliltä
- .{46,1439}: 46-1439 mielivaltaista tavua
Kun vertaamme tätä kahteen DPX-kuvaamme:
$ xxd kirkas.dpx | tail -1 017bb670: ebff fbeb fffb ebff fbeb fffb ebff fbeb ................
$ xxd tumma.dpx | tail -1 017bb670: 1400 0414 0004 1400 0414 0004 1400 0414 ................
huomaamme kirkkaan kuvan noudattavan MP3-tunnisteen alkuosaa. Kirkkaan kuvan jokainen pikseli on mahdollinen MP3-kehyksen alku ja FIDO:n täytyy etsiä eteenpäin vastaako loputkin tiedostosta MP3-tunnistetta. Tämä tapahtuu aina kolmen tavun välein. Tumma kuva puolestaan ei osu ollenkaan tähän säännölliseen lausekkeeseen.
Voimme verrata valitsemaamme väriä fffbeb MP3-kehyksen määrityksiin:
AAAAAAAA AAABBCCD EEEEFFGH
11111111 11111011 11101011
ff fb eb
mikä vastaisi MP3-kehystä:
- MPEG Version 1 (ISO/IEC 11172-3)
- Layer III
- Not protected by CRC
- Bitrate 320 kbps
- Sampling rate 32000 Hz
- Frame is padded with one extra slot
- Arbitrary private bit is set.
MP3-tiedostomuodon määritykset selittävät myös kuvien kirkkauden vaikutuksen koodin suoritusaikaan. Määrityksien mukaan MP3-kehyksen ensimmäiset 11 bittiä ovat aina päällä, minkä takia kirkkailla kuvilla on suurempi todennäköisyys osittain osua tähän säännölliseen lausekkeeseen. Tämä myös tarkoittaa, että täysin valkoinen ffffff ei toista virhettä. Virheen toistaa vain tietyt kirkkaat värisävyt, jotka osuvat osittain MP3-tunnisteen säännölliseen lausekkeeseen. Virheen toistavat värit fffb10-fffbeb kartoittuvat aurinkoiseksi kuvaksi:
Yhteenveto
Tutkimme mielenkiintoista virhettä missä tiedostomuodon tunnistus oli kolme kertaluokkaa hitaampaa kirkkailla DPX-kuvilla kuin tummilla DPX-kuvilla. Virheen aiheutti DPX-kuvan tarkka värisävy mikä muistutti MP3-tiedostojen PRONOM-tunnistetta. Kuvan jokainen pikseli vastasi MP3-kehyksen formaattia ja teki säännöllisten lausekkeiden suorittamisesta todella hidasta.
Tämän ymmärtämisen jälkeen varsinainen korjaus on triviaali. Voimme siirtää MP3-tunnisteet viimeisiksi ja etsiä niitä ainoastaan, jos emme ole jo tunnistaneet tiedostoa DPX-kuvaksi. Tämä korjaa DPX-tiedostojen käsittelyn rikkomatta MP3-tiedostojen tunnistamista, mutta mahdollisesti jättää perään vastaavia reunatapauksia muilla pakkaamattomilla tiedostomuodoilla.
Vastaavat ongelmat säännöllisten lausekkeiden kanssa eivät ole ennenkuulumattomia. Yksi laajalti tunnettu tapaus on Cloudflaren palvelukatko vuodelta 2019. Säännölliset lausekkeet mahdollistavat monimutkaisen etsintälogiikan pienellä vaivalla, mutta voivat olla vaikeasti ymmärrettäviä ja virhealttiita. Säännöllisiä lausekkeita ei voi aina välttää, mutta on hyvän käytännön mukaista yrittää ennen niihin turvautumista käyttää muita keinoja.
Juho Kuisma
0x5527DB198DF3508A