system time
Moderatorzy: Moderatorzy, Administratorzy
system time
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.
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.
Re: system time
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]
dienet
[img]http://i164.photobucket.com/albums/u19/slawek15/kotekeo0lq3.jpg[/img]
Re: system time
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.
Re: system time
Jeśli
Dodatkowo jak wyliczyłeś, że będzie się wykonywał o tyle, a tyle wolniej?
to zapewne w niej leży przyczyna problemu.Konfiguracja serwera jest dość skomplikowana
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]
dienet
[img]http://i164.photobucket.com/albums/u19/slawek15/kotekeo0lq3.jpg[/img]
Re: system time
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.
Re: system time
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...
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...
Re: system time
długo trwa sigsuspend, na przykład:
czy na podstawie powyższego listingu możesz powiedzieć co dalej?
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
...
Re: system time
Trzeba sprawdzić co robi proces potomny, bo tutaj akurat tylko czekamy na jego zakończenie. Użyj strace -f.
Re: system time
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 :
W przypadku serwera ten proces pochodny wykonywał się około 6 minut. Cały program na laptopie wykonuje się w mniej niż minutę.
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>
...
Re: system time
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Ć.
I napisz wreszcie CO TEN PROGRAM MA ROBIĆ.
Re: system time
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?
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]
dienet
[img]http://i164.photobucket.com/albums/u19/slawek15/kotekeo0lq3.jpg[/img]
Re: system time
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.
Re: system time
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).
Podaczas wykonywania tej linijki ze skruptu:
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>
Kod: Zaznacz cały
sfall mapin ${tempfile}sharp_solvent.map hklout ${tempfile}.mtz << EOF >> $logfile
Re: system time
Czy ktoś ma jeszcze jakieś pomysły?
Re: system time
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
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