O

d wersji 10.5 “Leopard”, Mac OS X posiada zestaw narzędzi o nazwie DTrace (ang. Dynamic Tracing Framework), który służy do analizy wydajności oraz rozwiązywania problemów z systemem. Zestaw ten dostarcza dane m.in dla narzędzi Apple Instruments, czy pozwala na wykorzystanie różnego rodzaju programów, które w rzeczywistości są skryptami DTrace. Autorem DTrace, jak i DTraceToolkit jest Brendan Gregg. Firma Apple po prostu dostosowała je do swojego systemu i umieściła jako standardowy pakiet oprogramowania Mac OS X.

Jak zaznacza sam autor DTrace może zostać wykorzystany, głównie do odpowiedzi na dwa pytania: – dlaczego mój Mac jest taki powolny? oraz – dlaczego mój wentylator zaczął tak głośno chodzić? W przeciwieństwie do DTrace – standardowe narzędzia do analizy, jak Monitor Aktywności (ang. Activity Monitor) oraz top(1) nie zawsze potrafią dostarczyć kluczowych informacji na temat aktywności programów w systemie np. jak wiele czasu procesora zajmują krótko żyjące procesy; które procesy powodują największe zużycie I/O dysku; ile czasu zajmuje odczyt / zapis danego procesu na dysku itd. Poniżej przedstawiam krótką listę i działanie niektórych skryptów DTrace:

1. iosnoop

– narzędzie to służy do “śledzenia” I/O dysku. Za każdym razem, kiedy operacja I/O się zakończy – na wyjściu programu wyświetlany jest wiersz z podsumowaniem całego procesu:

darkstar:~ root# iosnoop 
      UID  PID D    BLOCK   SIZE   COMM PATHNAME
160951430  366 R 48634712   4096  iTerm ??/com.googlecode.iterm.savedState/window_2.data
160951430  366 R 48634696   8192  iTerm ??/com.googlecode.iterm.savedState/window_2.data
160951430  366 W 48634712   4096  iTerm ??/com.googlecode.iterm.savedState/window_2.data
160951430  366 W 48634848  28672  iTerm ??/com.googlecode.iterm.savedState/window_2.data
160951430  366 W 48634904   4096  iTerm ??/com.googlecode.iterm.savedState/windows.plist
160951430  280 W 46685144  16384  Google Chrome ??/Default/Current Session
160951430  280 W 48635248 106496  Google Chrome ??/Default/.com.google.Chrome.zuK91F
    0        1 W 48048904  12288  launchd ??/T/etilqs_hF8gPlcMjfI2taD
    0        1 W 55170792   4096  launchd ??/asl/2012.04.30.U160951430.asl
    0        1 W 55171216   4096  launchd ??/asl/2012.04.30.U160951430.asl
    0        1 W 40742344   4096  launchd ??/log/system.log
    0        1 W 19899032   4096  launchd ??/asl/StoreData

Pozwala to na ciągłe monitorowanie aplikacji, które używają dysku oraz jakie pliki są przez nie czytane lub zapisywane. Operacje I/O na normalnych dyskach obrotowych nadal są wąskim gardłem w wydajności sprzętowej dlatego programy, które bardzo często żądają dostępu do danych (15 razy lub więcej na sekundę) mają prawo czasami wolniej wykonywać swoje funkcje ze względu na oczekiwanie na zakończenie operacji zapisu/odczytu. Prezentowane powyżej kolumny oznaczają kolejno: UID = użytkownik, PID = identyfikator procesu, D = rodzaj operacji (R = odczyt / W = zapis), BLOCK = położenie na dysku, SIZE = wielkość procesowanych danych w bajtach, COMM = nazwa procesu, PATHNAME = końcowa część ścieżki do pliku. W powyższym przykładnie została przyłapana przeglądarka Google Chrome na zapisywaniu bieżącej sesji ??/Default/Current Session. Jeśli zależy nam na bardziej szczegółowej analizie możemy wykorzystać parametry “-stoD“, które zwrócą timestamp’y każdego startu i końca operacji I/O wyrażone w microsekundach – plus opis kilku innych typów operacji również z informacjami czasowymi:

darkstar:~ root# iosnoop -stoD
STIME       TIME        DELTA  DTIME  UID  PID D    BLOCK  SIZE     COMM PATHNAME
4149708383  4149709133  750    768      0    1 W 41878792  4096  launchd ??/Cache/data_1

2. hfsslower.d

– skrypt ten tak naprawdę jest odpowiedzą na pytanie: – dlaczego iosnoop nie widzi wszystkich operacji I/O, jakie zachodzą na dysku? Odpowiedź jest prosta: w celu zwiększenia wydajności system plików zawsze będzie starał się cachować jak najwięcej danych w pamięci RAM. Czasami aplikacja wykonując operację odczytu “myśli”, że wykonuje odczyt z dysku – a tak naprawdę operacja ta jest wykonywana z bardzo szybkiej pamięci. Zapisy również mogą być buforowane w pamięci, a dopiero później zapisana wraz z innymi buforami na dysk, co również przyśpiesza działanie aplikacji. Skrypt hfsslower.d mierzy operacje I/O zanim zostaną one przetworzone przez system plików HFS+, a iosnoop mierzy je dopiero po przetworzeniu ich przez system plików i tylko jeśli dotrą do dysku. Dlatego można powiedzieć, że hfsslower.d jest w stanie zobaczyć znacznie więcej, w tym odzwierciedlić rzeczywistą wydajność aplikacji ze względu na pomiary opóźnienia, na które ona bezpośrednio cierpi. W dodatku hfsslower.d potrafi dostarczyć informacji o tym, że nie tylko wolne operacje I/O są powodowane przez dysk, ale na przykład może wystąpić zjawisko zakleszczenia w systemie plików (zjawisko to występuje kiedy jeden z procesów lub wątków przed uzyskaniem dostępu do zasobu próbuje uzyskać blokadę tego zasobu, która jest trzymana przez inny proces lub wątek). Skrypt ten pochodzi z książki DTrace i nie jest uwzględniony standardowo w dystrybucji systemu, dlatego można go ściągnąć stąd i przegrać z prawami 755 do katalogu /usr/local/bin. Jako argument może przyjąć liczbę określającą minimalną liczbę milisekund jaką zajęła operacja I/O:

[agresor@darkstar ~]$ sudo hfsslower.d 1
TIME                 PROCESS          D   KB     ms FILE
2012 May  1 13:33:46 esets_daemon     R    0     56 cursor.pdf/..namedfork/rsrc
2012 May  1 13:33:46 esets_daemon     R    4      7 cursor_1only_.png

Dlatego, jeśli użyjemy argumentu 0 będziemy w stanie śledzić każdą operację. Prezentowane powyżej kolumny oznaczają kolejno: TIME = czas zakończenia operacji I/O, PROCESS = nazwa aplikacji, D = rodzaj operacji (R = odczyt / W = zapis), KB = rozmiar operacji w Kilo Bajtach, ms = opóźnienie I/O w milisekundach, FILE = nazwa pliku, na którym wykonywana jest operacja.

3. execsnoop

– polecenie to śledzi wykonywanie nowych procesów. Szczególnie przydaje się w przypadku identyfikacji procesów o krótkim czasie życia tj. ich uruchomienie i zakończenie jest zbyt szybkie, aby wychwyciły je narzędzia typu top oraz Monitor Aktywności. Na przykład procesy te są uruchamiane podczas wykonania polecenia: ls man:

[agresor@darkstar ~]$ sudo execsnoop -v
STRTIME                UID    PID   PPID ARGS
2012 May  4 17:34:31 160951430    410     59 SFLSharedPrefsTo
2012 May  4 17:34:37 160951430    411    389 login
2012 May  4 17:34:37 160951430    412    411 bash
2012 May  4 17:34:37 160951430    414    413 path_helper
2012 May  4 17:34:42 160951430    415    412 man
2012 May  4 17:34:43 160951430    415    412 man
2012 May  4 17:34:43 160951430    415    412 man
2012 May  4 17:34:43 160951430    415    412 man
2012 May  4 17:34:43 160951430    416    415 sh
2012 May  4 17:34:43 160951430    416    415 gzip
2012 May  4 17:34:43 160951430    417    415 sh
2012 May  4 17:34:43 160951430    417    415 gzip
2012 May  4 17:34:43 160951430    425    424 less
2012 May  4 17:34:43 160951430    421    419 tbl
2012 May  4 17:34:43 160951430    426    422 troff
2012 May  4 17:34:43 160951430    423    420 sh
2012 May  4 17:34:43 160951430    423    420 gzip
2012 May  4 17:34:43 160951430    422    419 groff
2012 May  4 17:34:43 160951430    427    422 grotty

Prezentowane powyżej kolumny oznaczają kolejno: STRTIME = znacznik czasowy, UID = ID użytkownika, PID = ID procesu, PPID = ID rodzica procesu, ARGS = nazwa procesu (wyświetlane powinny być również argumenty przekazywane do procesów, ale nie działa to jeszcze w Mac OS X – więcej informacji na ten temat dostarcza pr_psargs w /usr/lib/dtrace/proc.d).

4. opensnoop

– pozwala na śledzenie plików, które są otwierane podczas uruchamiania programu. Pozwala to na wychwycenie różnego rodzaju błędów konfiguracyjnych, które zawierają złe ścieżki dostępu lub szczegółowo sprawdzić, co się dzieje podczas uruchamiania aplikacji:

[agresor@darkstar ~]$ sudo opensnoop -ve
STRTIME                UID   PID COMM          FD ERR PATH                 
2012 May  5 20:30:21     0   41 mds            9   0 .                    
2012 May  5 20:30:21     0  462 dtrace         6   0 /etc/localtime       
2012 May  5 20:30:22     0  463 launchdadd     3   0 /dev/dtracehelper    
2012 May  5 20:30:22     0  463 launchdadd     5   0 /var/db/launchd.db/com.apple.launchd 
2012 May  5 20:30:22     0  463 launchdadd     6   0 /var/db/launchd.db/com.apple.launchd 
2012 May  5 20:30:22     0  463 launchdadd     5   0 /usr/libexec         
2012 May  5 20:30:22     0  463 launchdadd     5   0 /usr/libexec/launchdadd 
2012 May  5 20:30:22     0   41 mds            9   0 .                    
2012 May  5 20:30:22    89  308 mdworker       9   0 /Library/PrivilegedHelperTools 
2012 May  5 20:30:28     0  276 esets_daemon  15   0 /etc/localtime       
2012 May  5 20:30:28     0  276 esets_daemon  15   0 /etc/localtime

Prezentowane powyżej kolumny oznaczają kolejno: STRTIME = znacznik czasowy, UID = ID użytkownika, PID = ID procesu, COMM = nazwa procesu / polecenie, FD = deskryptor pliku (-1 oznacza błąd ścieżki dostępu), ERR = kod błędu (szczegóły /usr/include/sys/errno.h), PATH = ścieżka dostępu.

5. dtruss

– poprzednie dwa narzędzia – opensnoop oraz execsnoop działały na podstawie śledzenia konkretnych wywołań systemowych. Wywołanie systemowe (ang. system call lub syscall) jest tym, o co aplikacja prosi jądro systemu operacyjnego kiedy przychodzi do wykonania uprzywilejowanego zadania, stworzenia procesu, operacji na plikach lub inne operacje I/O (dyskowe lub sieciowe). Wywołania systemowe są świetnym celem do analizy dla DTrace, ponieważ ich badanie często potrafi dostarczyć niezbędnych informacji (liczbę bajtów, nazwy plików i procesów, kody błędów, opóźnienia) o poczynaniach aplikacji. Narzędzie dtruss śledzi wszystkie rodzaje wywołań systemowych, co jest bardzo przydatne przy ogólnie pojętym debugowaniu (szczególnie, że Mac OS X tak naprawdę nie posiada typowego tracer’a syscall’i jak Linux “strace” lub Solaris “truss“). Jedną z zalet dtruss jest to, że może on śledzić kilka procesów w tym samym czasie – poprzez dopasowanie po nazwie procesu (opcja -n). Na przykład śledzenie przeglądarki Firefox po nazwie jej pliku binarnego:

[agresor@darkstar ~]$ sudo dtruss -n firefox-bin
	PID/THRD  SYSCALL(args) = return
  531/0x3738:  issetugid(0x100000000, 0x7FFF5FBFFDC9, 0x7FFF5FBFFC00) = 0 0
  531/0x3738:  csops(0x0, 0x0, 0x7FFF5FBFF84C) = 0 0
  531/0x3738:  shared_region_check_np(0x7FFF5FBFD798, 0x2, 0x55) = 0 0
  531/0x3738:  pread(0x3, "\312\376\272\276\0", 0x1000, 0x0) = 4096 0
  531/0x3738:  pread(0x3, "\317\372\355\376\a\0", 0x1000, 0x1000) = 4096 0
  531/0x3738:  mmap(0x100005000, 0x3000, 0x5, 0x12, 0x3, 0x100001F) = 0x5000 0
  531/0x3738:  mmap(0x100008000, 0x1000, 0x3, 0x12, 0x3, 0x100001F) = 0x8000 0
  531/0x3738:  mmap(0x100009000, 0x2C70, 0x1, 0x12, 0x3, 0x100001F) = 0x9000 0
  531/0x3738:  fcntl(0x3, 0x2C, 0x7FFF5FBFC678) = 0 0
  531/0x3738:  close(0x3) = 0 0
  531/0x3738:  stat64("/\0", 0x7FFF5FBFD2F0, 0x6) = 0 0
  531/0x3738:  getattrlist("/Applications\0", 0x7FFF684DC6F0, 0x7FFF5FBFD380) = 0 0
  531/0x3738:  getattrlist("/Applications/Firefox.app\0", 0x7FFF684DC6F0, 0x7FFF5FBFD380)

Ekran wyjściowy oczywiście jest znacznie dłuższy ze względu na wykonywanie bardzo dużej ilości wywołań. Jeśli ominiemy opcję -n – spowodujemy, że dtruss sam uruchomi wybraną aplikację i rozpocznie jej śledzenie. Dzięki wielu innym opcją możemy na przykład dodać znaczniki czasowe (-e), śledzić podprocesy (-f), sprawdzić ilość wywołań systemowych (-c) oraz wiele innych. Ryan Dahl (twórca node.js używał tak często narzędzia dtruss, że wprowadził własne usprawnienia i opublikował swoją wersję na github’ie.

6. soconnect_mac.d

– skrypt ten również nie wchodzi w standardowy zestaw narzędzi DTrace. Oczywiście można go ściągnąć w wgrać do systemu z oficjalnej strony książki poświęconej DTrace. Pozwala on na śledzenie wychodzących z systemu połączeń TCP.

[agresor@darkstar ~]$ sudo sconnect.d
PID    PROCESS          FAM ADDRESS          PORT   LAT(us) RESULT
534    ssh              2   11.111.11.11     22       39993 Success
19     opendirectoryd   2   12.123.12.123    389        107 In progress
543    Adium            2   22.222.222.222   5222        88 In progress
543    Adium            2   32.32.321.32     5222       113 In progress

Istnieje również narzędzie o nazwie soaccept_mac.d, które służy z kolei do śledzenia połączeń przychodzących.

7. errinfo

– narzędzie to dostarcza podsumowania, które z wywołań systemowych zakończyły się błędem. Oprócz kodu błędu możemy uzyskać krótki opis kodu oraz nazwę procesu, który go wygenerował. Dzięki temu możemy szybko wyśledzić źle skonfigurowane lub nieprawidłowo obsługujące kody błędów aplikacje:

[agresor@darkstar ~]$ sudo errinfo
            EXEC          SYSCALL  ERR  DESC
            ntpd       sigsuspend    4  Interrupted system call 
            ntpd        sigreturn   -2 
            ntpd __pthread_canceled   22  Invalid argument
          iTerm             read   35  Resource temporarily unavailable 
        perl5.12             read    4  Interrupted system call 
        perl5.12        sigreturn   -2 
        perl5.12 __pthread_canceled   22  Invalid argument

Innymi ciekawymi skryptami są:

• bitesize.d – charakterystyka rozkładu obciążenia I/O dysku według programów z podliczaniem liczby bajtów,
• iotop – funkcjonalnością to samo narzędzie, co iosnoop, lecz prezentujące dane bardzo podobnie do narzędzia top,
• maclife.d – skrypt śledzący tworzenie i kasowanie plików.

Oprócz w/w skryptów w systemie Mac OS X istnieje jeszcze wiele narzędzi – wystarczy w konsoli uruchomić polecenie: man -k dtrace, aby naszym oczom ukazała się pełna lista:

bitesize.d(1m)           - analyse disk I/O size by process. Uses DTrace
cpuwalk.d(1m)            - Measure which CPUs a process runs on. Uses DTrace
creatbyproc.d(1m)        - snoop creat()s by process name. Uses DTrace
dappprof(1m)             - profile user and lib function usage. Uses DTrace
dapptrace(1m)            - trace user and library function usage. Uses DTrace
diskhits(1m)             - disk access by file offset. Uses DTrace
dispqlen.d(1m)           - dispatcher queue length by CPU. Uses DTrace
dtrace(1)                - generic front-end to the DTrace facility
dtruss(1m)               - process syscall details. Uses DTrace
errinfo(1m)              - print errno for syscall fails. Uses DTrace
execsnoop(1m)            - snoop new process execution. Uses DTrace
fddist(1m)               - file descriptor usage distributions. Uses DTrace
filebyproc.d(1m)         - snoop opens by process name. Uses DTrace
hotspot.d(1m)            - print disk event by location. Uses DTrace
httpdstat.d(1m)          - realtime httpd statistics. Uses DTrace
iofile.d(1m)             - I/O wait time by file and process. Uses DTrace
iofileb.d(1m)            - I/O bytes by file and process. Uses DTrace
iopattern(1m)            - print disk I/O pattern. Uses DTrace
iopending(1m)            - plot number of pending disk events. Uses DTrace
iosnoop(1m)              - snoop I/O events as they occur. Uses DTrace
iotop(1m)                - display top disk I/O events by process. Uses DTrace
kill.d(1m)               - snoop process signals as they occur. Uses DTrace
lastwords(1m)            - print syscalls before exit. Uses DTrace
loads.d(1m)              - print load averages. Uses DTrace
newproc.d(1m)            - snoop new processes. Uses DTrace
opensnoop(1m)            - snoop file opens as they occur. Uses DTrace
pathopens.d(1m)          - full pathnames opened ok count. Uses DTrace
pidpersec.d(1m)          - print new PIDs per sec. Uses DTrace
plockstat(1)             - front-end to DTrace to print statistics about POSIX 
                           mutexes and read/write locks
priclass.d(1m)           - priority distribution by scheduling class. Uses DTrace
pridist.d(1m)            - process priority distribution. Uses DTrace
procsystime(1m)          - analyse system call times. Uses DTrace
runocc.d(1m)             - run queue occupancy by CPU. Uses DTrace
rwbypid.d(1m)            - read/write calls by PID. Uses DTrace
rwbytype.d(1m)           - read/write bytes by vnode type. Uses DTrace
rwsnoop(1m)              - snoop read/write events. Uses DTrace
sampleproc(1m)           - sample processes on the CPUs. Uses DTrace
seeksize.d(1m)           - print disk event seek report. Uses DTrace
setuids.d(1m)            - snoop setuid calls as they occur. Uses DTrace
sigdist.d(1m)            - signal distribution by process. Uses DTrace
syscallbypid.d(1m)       - syscalls by process ID. Uses DTrace
syscallbyproc.d(1m)      - syscalls by process name. Uses DTrace
syscallbysysc.d(1m)      - syscalls by syscall. Uses DTrace
topsyscall(1m)           - top syscalls by syscall name. Uses DTrace
topsysproc(1m)           - top syscalls by process name. Uses DTrace
weblatency.d(1m)         - website latency statistics. Uses DTrace

Plus te dostępne na stronie książki o DTrace. Na koniec wypada przypomnieć, że DTrace nie tylko służy do wykonywania skryptów, ale jako framework umożliwia pisanie własnych programów, skryptów, czy jednolinijkowców. I nie chodzi tylko o MacBooki, ale jeśli używamy serwerów opartych na systemie operacyjnym Solaris lub FreeBSD możemy wykorzystać te wszystkie skrypty do codziennych prac administracyjnych i diagnozy problemów wydajnościowych.

Więcej informacji: DTrace Tools, Solaris Dynamic Tracing Guide, Top 10 DTrace scripts for Mac