system time

Te, które nie mieszczą się w powyższych kategoriach, a mają coś wspólnego ze Slackware.

Moderatorzy: Moderatorzy, Administratorzy

pankracy
Użytkownik
Posty: 17
Rejestracja: 2007-05-24, 23:12
Lokalizacja: kr

system time

Post autor: pankracy »

Witam serdecznie,

być może ktoś z Was jest w stanie rozwikłać pewną zagadkę, którą ani ja ani moi administratorzy "do bani" do tej pory nie umieli wyjaśnić. Jest sobie pewien serwer, czas który system poświęca na tzw. system calls jest niepokojąco długi. Konsekwentnie ten "wypasiony" serwer działa wolniej niż przykładowy, zwyczajny laptop.

Ten sam program na laptopie poświęca tyle czasu na swoje wykoanie:
34.00 real 19.72 user 2.02 sys

a na wspomnianym serwerze aż:
21.14s user 755.21s system 98% cpu 13:04.37 total.

Oczywiście byłoby fajnie znaleźć przyczynę problemu i go naprawić. Konfiguracja serwera jest dość skomplikowana, dlatego wolałbym nie wklejać wszystkiego teraz.

Z góry dziękuję za odpowiedzi i pozdrawiam.
Awatar użytkownika
dienet
Moderator
Posty: 2105
Rejestracja: 2007-07-24, 18:58
Lokalizacja: Racibórz/Rybnik

Re: system time

Post autor: dienet »

A dlaczego wychodzisz z założenia że na super hiper serwerze akurat ten program będzie wykonywał się szybciej?
Pozdr0
dienet
[img]http://i164.photobucket.com/albums/u19/slawek15/kotekeo0lq3.jpg[/img]
pankracy
Użytkownik
Posty: 17
Rejestracja: 2007-05-24, 23:12
Lokalizacja: kr

Re: system time

Post autor: pankracy »

Ten program powinien wykonać się troszkę wolniej na serwerze niż na laptopie. Przez "troszkę" rozumiem czas rzędu 2-3 sekund, nie 12 minut jak w powyższym przykładzie. Wychodzę z takiego założenia ponieważ wiem co ten program ma robić. Skoro wykonuje się wolniej na serwerze coś jest nie tak z jego konfiguracją. Byłbym wdzięczny chociaż za naprowadzenie na trop źródła tego problemu.
Awatar użytkownika
dienet
Moderator
Posty: 2105
Rejestracja: 2007-07-24, 18:58
Lokalizacja: Racibórz/Rybnik

Re: system time

Post autor: dienet »

Jeśli
Konfiguracja serwera jest dość skomplikowana
to zapewne w niej leży przyczyna problemu.

Dodatkowo jak wyliczyłeś, że będzie się wykonywał o tyle, a tyle wolniej?
Pozdr0
dienet
[img]http://i164.photobucket.com/albums/u19/slawek15/kotekeo0lq3.jpg[/img]
pankracy
Użytkownik
Posty: 17
Rejestracja: 2007-05-24, 23:12
Lokalizacja: kr

Re: system time

Post autor: pankracy »

Właśnie, zrzucamy winę na konfiguracje. Gdyby ktoś mógł mnie naprowadzić na to które ustawienie mogłoby być przyczyną spowolnienia, mógłbym je zmienić i przetestować reakcję. Nie wyliczyłem o ile wolniej będzie się wykonywał tylko oszacowałem biorąc pod uwagę różnice w modelu procesora. Oczywiście to jest trochę niepełne porównanie.
joi
Użytkownik
Posty: 151
Rejestracja: 2004-10-12, 20:32
Lokalizacja: raczej nie stąd ;)
Kontakt:

Re: system time

Post autor: joi »

Stracem sprawdź które to wywołania systemowe trwają długo.
Sprawdź co pokazuje perf top, ewentualnie nagraj perfem całą sesję (perf record -gR program) i przeanalizuj perf reportem.

Jeżeli nic nie wyczytasz z powyższych narzędzi, będziesz musiał napisać co ten program robi...
pankracy
Użytkownik
Posty: 17
Rejestracja: 2007-05-24, 23:12
Lokalizacja: kr

Re: system time

Post autor: pankracy »

długo trwa sigsuspend, na przykład:

Kod: Zaznacz cały

...
23:58:54.799197 open("/tmp/sh29829", O_RDWR|O_CREAT|O_EXCL, 0600) = 0 <0.000148>
23:58:54.799712 unlink("/tmp/sh29829")  = 0 <0.000056>
23:58:54.799853 write(0, "    mode mapin1 mapin2\n    maps "..., 36) = 36 <0.000107>
23:58:54.800036 lseek(0, 0, SEEK_SET)   = 0 <0.000018>
23:58:54.800121 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffff7fe39d0) = 36754 <0.000741>
23:58:54.801027 gettimeofday({1345759134, 801043}, NULL) = 0 <0.000011>
23:58:54.801082 rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0 <0.000010>
23:58:54.801136 rt_sigsuspend([])       = ? ERESTARTNOHAND (To be restarted) <14.010172>
23:59:08.811544 --- SIGCHLD (Child exited) @ 0 (0) ---
23:59:08.811730 rt_sigreturn(0x11)      = -1 EINTR (Interrupted system call) <0.000070>
23:59:08.811874 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, {ru_utime={1, 4847}, ru_stime={12, 866044}, ...}) = 36754 <0.000159>
23:59:08.812219 wait4(-1, 0x7fffffffcdb0, WNOHANG, 0x7fffffffcd20) = -1 ECHILD (No child processes) <0.000138>
23:59:08.812577 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000058>
23:59:08.812848 alarm(0)                = 0 <0.000080>
23:59:08.813026 alarm(0)                = 0 <0.000011>
23:59:08.813122 close(0)                = 0 <0.000289>
23:59:08.813440 dup(19)                 = 0 <0.000015>
23:59:08.813478 fcntl(0, F_SETFD, 0)    = 0 <0.000024>
23:59:08.813532 close(1)                = -1 EBADF (Bad file descriptor) <0.000012>
23:59:08.813569 dup(17)                 = 1 <0.000016>
23:59:08.813615 fcntl(1, F_SETFD, 0)    = 0 <0.000020>
23:59:08.813693 close(2)                = -1 EBADF (Bad file descriptor) <0.000011>
23:59:08.813747 dup(18)                 = 2 <0.000009>
23:59:08.813780 fcntl(2, F_SETFD, 0)    = 0 
...
czy na podstawie powyższego listingu możesz powiedzieć co dalej?
joi
Użytkownik
Posty: 151
Rejestracja: 2004-10-12, 20:32
Lokalizacja: raczej nie stąd ;)
Kontakt:

Re: system time

Post autor: joi »

Trzeba sprawdzić co robi proces potomny, bo tutaj akurat tylko czekamy na jego zakończenie. Użyj strace -f.
pankracy
Użytkownik
Posty: 17
Rejestracja: 2007-05-24, 23:12
Lokalizacja: kr

Re: system time

Post autor: pankracy »

dzięki za podpowiedzi i zainteresowanie, sprawdziłem strace'm -f, nie wiem czy poprawnie ale
proces potomny jest wypełniony tego typu zajęciami, wypełniają one większą część czasu jego wykonania :

Kod: Zaznacz cały

...
21:13:57.410835 lseek(4, -8388128, SEEK_CUR) = 10544384 <0.000063>
21:13:57.411034 lseek(4, 0, SEEK_CUR)   = 10544384 <0.000074>
21:13:57.411254 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.005139>
21:13:57.416559 lseek(4, -8388128, SEEK_CUR) = 10544864 <0.000064>
21:13:57.416725 lseek(4, 0, SEEK_CUR)   = 10544864 <0.000069>
21:13:57.416902 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.005063>
21:13:57.422123 lseek(4, -8388128, SEEK_CUR) = 10545344 <0.000066>
21:13:57.422312 lseek(4, 0, SEEK_CUR)   = 10545344 <0.000096>
21:13:57.422535 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\16\2\253>"..., 8388608) = 8388608 <0.004922>
21:13:57.427614 lseek(4, -8388128, SEEK_CUR) = 10545824 <0.000059>
21:13:57.427797 lseek(4, 0, SEEK_CUR)   = 10545824 <0.000074>
21:13:57.428018 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\16\2\253>\16\2\253>\16\2\253>\16\2\253>\16\2\253>"..., 8388608) = 8388608 <0.004844>
21:13:57.433037 lseek(4, -8388128, SEEK_CUR) = 10546304 <0.000103>
21:13:57.433257 lseek(4, 0, SEEK_CUR)   = 10546304 <0.000062>
21:13:57.433474 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\16\2\253>\16\2\253>\16\2\253>\16\2\253>\16\2\253>"..., 8388608) = 8388608 <0.004866>
21:13:57.438511 lseek(4, -8388128, SEEK_CUR) = 10546784 <0.000061>
21:13:57.438710 lseek(4, 0, SEEK_CUR)   = 10546784 <0.000070>
21:13:57.438921 read(4, "\0\0\0\0\0\0\0\0\16\2\253>\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\16\2\253>"..., 8388608) = 8388608 <0.004954>
21:13:57.444034 lseek(4, -8388128, SEEK_CUR) = 10547264 <0.000062>
21:13:57.444215 lseek(4, 0, SEEK_CUR)   = 10547264 <0.000074>
21:13:57.444424 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.005060>
21:13:57.449666 lseek(4, -8388128, SEEK_CUR) = 10547744 <0.000066>
21:13:57.449857 lseek(4, 0, SEEK_CUR)   = 10547744 <0.000075>
21:13:57.450093 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.005136>
21:13:57.455420 lseek(4, -8388128, SEEK_CUR) = 10548224 <0.000101>
21:13:57.455640 lseek(4, 0, SEEK_CUR)   = 10548224 <0.000076>
21:13:57.455858 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.005042>
21:13:57.461074 lseek(4, -8388128, SEEK_CUR) = 10548704 <0.000062>
21:13:57.461242 lseek(4, 0, SEEK_CUR)   = 10548704 <0.000059>
21:13:57.461427 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.004783>
21:13:57.466384 lseek(4, -8388128, SEEK_CUR) = 10549184 <0.000238>
21:13:57.466746 lseek(4, 0, SEEK_CUR)   = 10549184 <0.000251>
21:13:57.467247 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.004953>
21:13:57.472374 lseek(4, -8388128, SEEK_CUR) = 10549664 <0.000066>
21:13:57.472564 lseek(4, 0, SEEK_CUR)   = 10549664 <0.000076>
21:13:57.472751 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.004981>
21:13:57.477874 lseek(4, -8388128, SEEK_CUR) = 10550144 <0.000061>
21:13:57.478064 lseek(4, 0, SEEK_CUR)   = 10550144 <0.000073>
21:13:57.478281 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8388608) = 8388608 <0.005060>
21:13:57.483690 lseek(4, -8388128, SEEK_CUR) = 10550624 <0.000068>
21:13:57.483871 lseek(4, 0, SEEK_CUR)   = 10550624 <0.000075>
21:13:57.484073 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\16\2\253>\16\2\253>"..., 8388608) = 8388608 <0.004822>
21:13:57.489051 lseek(4, -8388128, SEEK_CUR) = 10551104 <0.000073>
...
W przypadku serwera ten proces pochodny wykonywał się około 6 minut. Cały program na laptopie wykonuje się w mniej niż minutę.
joi
Użytkownik
Posty: 151
Rejestracja: 2004-10-12, 20:32
Lokalizacja: raczej nie stąd ;)
Kontakt:

Re: system time

Post autor: joi »

Program w kółko czyta 8MB danych z tego samego miejsca w tym samym pliku. Żeby dowiedzieć się z jakiego pliku, poszukaj ostatniego open'a zwracającego 4 (numer deskryptora pliku przekazywanego do read/lseek) lub sprawdź do czego prowadzi link /proc/pid_procesu/fd/numer_deskryptora.

I napisz wreszcie CO TEN PROGRAM MA ROBIĆ.
Awatar użytkownika
dienet
Moderator
Posty: 2105
Rejestracja: 2007-07-24, 18:58
Lokalizacja: Racibórz/Rybnik

Re: system time

Post autor: dienet »

Nie czyta z tego samego miejsca. Zwróć uwagę na zwroty z lseek.
Wydaje mi się, że masz problem z wielowątkowością a nie z samą maszyna. Testowałeś to na ilu maszynach?
In any project that is multi-threaded, most bugs will come from threading issues. This is regardless of programming language -- it's a deep, as yet ununderstood property of threads.
Guido van Rossum
Pozdr0
dienet
[img]http://i164.photobucket.com/albums/u19/slawek15/kotekeo0lq3.jpg[/img]
Pajaczek
Użytkownik
Posty: 1439
Rejestracja: 2006-08-03, 13:16
Lokalizacja: Winny Gród

Re: system time

Post autor: Pajaczek »

Tia... lseek cofa o mniej niż 8MB. Różnica to 480B za każdym razem. Czy ten program nie szuka przypadkiem czegoś w pliku o deskryptorze 4, jakiegoś wzorca? Może masz na tym serwerze inne dane wejściowe? Btw. ten drugi lseek jest też dziwny.
pankracy
Użytkownik
Posty: 17
Rejestracja: 2007-05-24, 23:12
Lokalizacja: kr

Re: system time

Post autor: pankracy »

Testowałem na 1 maszynie, swoim laptopie, skrypt który odpalam używa kilku ogólnie dostępnych programów, opiera się na tym:
http://www.ccp4.ac.uk/html/sfall.html.

Skrypt (trochę zmodyfikowany) znajduje się tu http://bl831.als.lbl.gov/~jamesh/mlfsom/ano_sfall.com.

Co masz na myśli mówiąc wielowątkowość i problem? Raczej używam programy niż je tworzę i nie posiadam obszernej wiedzy z dziedzin administracja systemem i programowanie ;)
Chciałbym z Waszą pomocą zlokalizować i naprawić problem związany z serwerem, który poświęca zbyt dużo czasu na wykonanie zadań. Nie tylko ten program wykonuje się wolniej na tym srewerze niż na laptopie. Zwykła kompilacja, np biblioteki fftw zajmuje mu kilka razy dłużej. Wnioskuje więc, że to problem z serwerem.

We wcześniej przedstawionym listingu program czytał z: tempfilesharp_solvent.map (rozmiar: 37633664).

Kod: Zaznacz cały

21:12:02.060799 open("tempfilesharp_solvent.map", O_RDONLY) = 4 <0.000021>
Podaczas wykonywania tej linijki ze skruptu:

Kod: Zaznacz cały

sfall mapin ${tempfile}sharp_solvent.map hklout ${tempfile}.mtz << EOF >> $logfile
pankracy
Użytkownik
Posty: 17
Rejestracja: 2007-05-24, 23:12
Lokalizacja: kr

Re: system time

Post autor: pankracy »

Czy ktoś ma jeszcze jakieś pomysły?
Awatar użytkownika
gienek
Użytkownik
Posty: 25
Rejestracja: 2011-05-18, 12:29

Re: system time

Post autor: gienek »

Nie napisałeś co to za dystrybucje, platformy na serwerze i laptopie.
Czy program jest zlinkowany statycznie bo może masz różne wersje bibliotek na dwóch kompach (pisząc o wersji mam na uwadze nie nazwę pliku).
Czy próbowałeś wyłączyć w biosie hyper-threadingi (np. niektóre programy tego "nie lubią" tzn. wolniej pracują bo procek przewala watki miedzy wirtualnymi prockami).
Czy masz zainstalowane antywirusy.
Czy dysponujesz kodem źródłowym programu.
Co było do na tych komputerach zmieniane doinstalowywane, opcje kompilacji jądra itd.
Raczej nikt ci nie rozwiąże tego problemu nie będąc przy tym sprzęcie sam widzisz ile niewiadomych a jeszcze ich kilka pewnie bym znalazł.
Pozdrawiam
ODPOWIEDZ