Przetwarzanie logów? Proszę bardzo!

wrzesień 18, 2007 at 15:54 · Kategoria wpisu: Recepty, Narzędzia

Przydarzyła mi się ostatnio konieczność napisania konwertera do logów. Chodziło z grubsza o zamianę logów wyplutych z aplikacji railsowej na format khm khm XML :) tak aby można było logi wygodnie analizować za pomocą narzędzia Apache Chainsaw (o sposobie wykorzystania tego narzędzia w Railsach pisałem już wcześniej ). Sprawa wydaje się trywialnie prosta, piszemy kawałek kodu w Rubym który wczytuje poszczególne linie z pliku wejściowego, a każdą linię poddaje działaniu RegExpów i sprawa gotowa ale...

doświadczenie pokazuje, że takie podejście zwykle kończy się to powstaniem kodu "write once, read never". Tym razem postanowiłem powertować The Ruby Way w poszukiwaniu wygodniejszego sposobu niż tasiemcowe RegExpy... i natrafiłem na klasę StringScanner. Z jej pomocą zadanie stało się znacznie wygodniejsze w implementacji i mam wrażenie także czytelniejsze. StringScanner ułatwia podział ciągu znaków na poszukiwane fragmenty (czasem nazywane tokens). Są wyodrębniane albo za pomocą dopasowania RegExpami albo za pomocą przesunięcia wewnętrznego indexu skanera na określoną pozycję w analizowanym ciągu (np. przeskocz do 10-tego znak). W praktyce zastosowanie StringScannera wygląda następująco:

PLAIN TEXT
RUBY:
  1. # Przykładowa linia z loga
  2. line = "2007-09-18 12:28:49 INFO  logger (app/controllers/application.rb:88:in `log_processing') - [GET] AuthController.index"
  3.  
  4. # Format:
  5. # 2007-09-18 12:28:49 - timestamp wpisu
  6. # INFO - poziom logowania
  7. # logger - nazwa loggera
  8. # (...) - informacja o miejscu wywolania, do ominięcia
  9. # [GET] AuthController .... - wiadomosc zapisana w logach
  10.  
  11. # Analiza linii ma wyciągnąc z niej dane przedstawione powyżej
  12. require 'strscan'
  13. scanner = StringScanner.new(line)
  14.  
  15. # dopasowanie do calego time stampa
  16. timestamp = scanner.scan(/^\d{4}\-\d{2}\-\d{2} \d{2}:\d{2}:\d{2}/)
  17.  
  18. # przeskoczenie pustych znakow pomiedzy ts a INFO
  19. scanner.skip(/\s+/)
  20.  
  21. # level to jedno slowo
  22. level = scanner.scan(/\w+/)
  23.  
  24. # spacje pomiedzy INFO a logger do przeskoczenia
  25. scanner.skip(/\s+/)
  26.  
  27. logger = scanner.scan(/\w+/)
  28.  
  29. # inny sposob przeskoczenia - wiem ze jest tylko jedna spacja
  30. # pomiedzy logger a (app/controller...) zmieniam wiec wewnętrzną pozycję
  31. # zapamietana przez skaner zamiast przez scanner.skip(/\s+/)
  32. scanner.pos += 1
  33.  
  34. # omijam wszystko az do zakonczenia danych z trace'a do napotkania ciagu ') - '
  35. # ktory wystepuje przed komunikatem
  36. scanner.skip_until(/\) - /)
  37.  
  38. # wiadomosc zapisana jest do konca linii
  39. message = scanner.post_match
  40.  
  41. # i efekt na koncu
  42. puts %Q(#{timestamp}\t#{logger}\t#{level}\t#{message})

Dla wprawki jeszcze analogiczny kod zrealizowany tylko za pomocą RegExpów:

PLAIN TEXT
RUBY:
  1. # Dla porównania jeszcze wersja klasyczna - korzystająca tylko z regexpów
  2. r = Regexp.new('^(\d{4}\-\d{2}\-\d{2} \d{2}:\d{2}:\d{2})\s+(\w+)\s+(\w+)\s+\(.*?\) - (.*)')
  3. match_data = r.match(line)
  4. timestamp = match_data[1]
  5. level = match_data[2]
  6. logger = match_data[3]
  7. message = match_data[4]
  8. # i efekt na koncu
  9. puts %Q(#{timestamp}\t#{logger}\t#{level}\t#{message})

Skoro już mamy dwie wersje kodu wstyd byłoby nie porównać ich wydajności :)

PLAIN TEXT
RUBY:
  1. Rehearsal ---------------------------------------------
  2. strscan     0.266667   0.016667   0.283333 (  0.165437)
  3. regexp      0.983333   0.016667   1.000000 (  0.609420)
  4. ------------------------------------ total: 1.283333sec
  5.  
  6.                 user     system      total        real
  7. strscan     0.266667   0.000000   0.266667 (  0.164356)
  8. regexp      0.866667   0.016667   0.883333 (  0.516766)

Jak widać czytelniejszy kod jest w dodatku szybszy! Oto niespodziewany uboczny efekt dążenia do doskonałości :)

Aktualizacja

Po uwzględnieniu zmiany zgłoszonej przez ciukesa (wyciągnięcie tworzenia RegExpa poza pętlę) wyniki dla RegExp oczywiście są lepsze, ale nadal StringScanner jest najszybszy. Dla porównania dodałem też różne sposoby tworzenia RegExpów

PLAIN TEXT
RUBY:
  1. Rehearsal ----------------------------------------------
  2. strscan      0.333333   0.000000   0.333333 (  0.201591)
  3. regexp new   1.016667   0.016667   1.033333 (  0.620982)
  4. regexp r     0.466667   0.000000   0.466667 (  0.283883)
  5. regexp //    0.466667   0.000000   0.466667 (  0.290693)
  6. regexp %r    0.466667   0.000000   0.466667 (  0.275177)
  7. ------------------------------------- total: 2.766667sec
  8.  
  9.                  user     system      total        real
  10. strscan      0.300000   0.000000   0.300000 (  0.183991)
  11. regexp new   0.916667   0.016667   0.933333 (  0.574049)
  12. regexp r     0.516667   0.000000   0.516667 (  0.315777)
  13. regexp //    0.416667   0.000000   0.416667 (  0.247187)
  14. regexp %r    0.500000   0.016667   0.516667 (  0.306069)

[ ]
Spodobało się? Podziel się z innymi: These icons link to social bookmarking sites where readers can share and discover new web pages.
  • del.icio.us
  • Wykop
  • Gwar
  • Digg
  • Technorati

1 komentarz »

  1. ciukes said,

    wrzesień 19, 2007 @ 18:21

    Czy moglbys powtorzyc pomiar z drobna zmiana?
    W http://static.jarmark.org/scanner/scanner_benchmark.rb przesun linie:
    r=Regexp.new….
    poza petle.

RSS feed for comments on this post · Adres TrackBack

Dodaj komentarz