From kloczek@boss.zie.pg.gda.pl Thu Sep 22 15:51:45 2005 Path: news.gazeta.pl!newsfeed.pionier.net.pl!news.task.gda.pl!not-for-mail From: Tomasz =?UTF-8?Q?K=C5=82oczko?= Newsgroups: pl.comp.os.linux Subject: Re: syslogd i =?UTF-8?Q?wydajno=C5=9B=C4=87?= Date: Wed, 21 Sep 2005 17:07:50 +0000 (UTC) Organization: CI TASK http://news.task.gda.pl/ Lines: 121 Message-ID: References: NNTP-Posting-Host: boss.zie.pg.gda.pl Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-Trace: news.task.gda.pl 1127322470 13826 153.19.33.230 (21 Sep 2005 17:07:50 GMT) X-Complaints-To: abuse@news.task.gda.pl NNTP-Posting-Date: Wed, 21 Sep 2005 17:07:50 +0000 (UTC) X-Organization-Notice: Organization line has been filtered User-Agent: tin/1.7.9-20050629 ("Grimsay") (UNIX) (Linux/2.6.13-1.1552sp1smp (sparc64)) X-Original-Organization: CI TASK http://www.task.gda.pl/ Xref: news.gazeta.pl pl.comp.os.linux:1137217 Tomasz Torcz wrote: > Dzięki, Łukasz, za post o treści: >> Witam, >> >> podpowiedzcie mi proszę, na ile to jest normalne: >> MaszynaA w syslog.conf ma: >> *.* @MaszynaB >> >> mam też plik.txt na MaszynieA z liniami >> 1 >> 2 >> 3 >> .. >> 1000 >> >> daję: >> cat plik.txt | logger -p local2.info >> >> na MaszynaB mam co trzeba, by local2.info znalazło się w osobnym pliku. >> I w pliku tym znajduję się średnio 65% tego, co powinno. >> To standardowa niewydolność sysloga? >> Da się temu jakoś zaradzić? > > Syslog pcha wszystko przez UDP. To stratny protokół. Może to przez to? .. lub po TCP o ile używa się np. syslog-ng czy kilku innych i to tylko gdy logi są skłądowane nie w lokalnie dostępnych zasobach plikowych tylko na zdalnym syslog serwerze. Lokalnie logger z syslogd komunikuje się poprzez: $ file /dev/log /dev/log: socket Ładnie to wydać jak zapuści się: $ echo "eciepecie" | strace logger -p local2.info 2>&1 | tail -n 10 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=976, ...}) = 0 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=976, ...}) = 0 socket(PF_FILE, SOCK_DGRAM, 0) = 1 <=== _TUTAJ_ fcntl64(1, F_SETFD, FD_CLOEXEC) = 0 connect(1, {sa_family=AF_FILE, path="/dev/log"}, 16) = 0 <=== _TUTAJ_ send(1, "<150>Sep 21 18:55:55 logger: eci"..., 38, MSG_NOSIGNAL) = 38 read(0, "", 4096) = 0 close(1) = 0 exit_group(0) = ? Process 8982 detached Tak czy inaczej .. tym wypadku chodzi o zupełnie coś innego. Mianowicie o to, że syslogd standardowo odbiera komunikat linijka po linijce z tego gniazdka, a po odebraniu i wrzuceniu tego do pliku (o ile komunikat metoda składowania nie przewiduje odesłania komunikatu do innego syslog servera po sieci) i po wykonaniu write() wykonywany jest fsync(). Dopiero po wykonaniu tych operacji syslogd zabiera się za odbieranie kolejnego komunikatu. To co w międzyczasie idzie do /dev/log może pójść (jak widać na przykładzie) na /dev/drzewo. Taka komunikacja ma mniejwiecej te same wady co rozmowa z głuchym potrafiącym czytać z ruchu ust ("słyszy" on nas tylko wtedy kiedy na nas patrzy). Widać to będzie jak przed powyższym strace z loggerem zapuści się innego terminal z root-a: # strace -p `pidof syslogd` Po każdym wołaniu loggera na wyjściu powyższego pojawi się coś na kształt: Process 2858 attached - interrupt to quit select(1, [0], NULL, NULL, NULL) = ? ERESTARTNOHAND (To be restarted) --- SIGALRM (Alarm clock) @ 0 (0) --- rt_sigaction(SIGALRM, {0x362f47, [ALRM], 0}, {0x362f47, [ALRM], 0}, 8) = 0 alarm(30) = 0 rt_sigaction(SIGALRM, NULL, {0x362f47, [ALRM], 0}, 8) = 0 rt_sigaction(SIGALRM, {0x362f47, [ALRM], 0}, NULL, 8) = 0 sigreturn() = ? (mask now []) select(1, [0], NULL, NULL, NULL) = 1 (in [0]) recv(0, "<150>Sep 21 18:57:19 logger: eci"..., 1022, 0) = 38 time([1127320279]) = 1127320279 writev(1, [{"Sep 21 18:57:19", 15}, {" ", 1}, {"test1", 5}, {" ", 1}, {"logger: eciepecie", 17}, {"\n", 1}], 6) = 40 fsync(1) = 0 <========= _TUTAJ_ select(1, [0], NULL, NULL, NULL Częste wykonywanie fsync() powoduje że proces syslogd neimal zawłaszcza dosŧęp do zasobów plikowych. Typowo dyski IDE wytrzymują max koło stu I/O na sekundę (dla przykłądu SCSI 320 ~300) więc w sumie o ile w systemie o ile coś innego jeszcze grzebie na dyskach na których leży /var/log to zatkać to od tego końca jest .. bajecznie prosto. Konsekwencja powyższego -> bardzo szybko rośnie load bo wydłuża się kolejka runing procesów czekających na zakończenie własnych operacji wejścia/wyjścia które z kolejki I/O wypychane czy (lepiej byłoby powidzieć) wręcz nie dopuszczane są do niej przez syslogd. Zabawa z tuningiem np. I/O schedulerem na mało się zda bo "kołdra jest bardzo krótka". Rozwiązanie: zmienić metotę składowania logów z domyślnej synchronicznej (wymagającej fsync()) na asynchroniczną tak żeby syslogd mógł szybciej odbierać z /dev/log. W klasycznym BSD syslogd na jakim bazuje popularnie używany syslogd w większości dystrybucji robi się to porzez dostawienie znaku "-" przez nazwą pliku w syslog.conf (co jest ładnie opisane w manie do tego pliku). Druga sprawa to to że i to może być za mało gdyż syslogd odbiera jednym procesem wszystkio z /dev/log. Będzie to istotne w przypadku np. odbierania komunikatów z kilku aplikacji równocześnie (szczególnie na maszynach SMP). Tu by trzeba np. sportować syslogd z Solarisa który od conajmniej już kilku lat jest zwątkowany (źródła sa dosŧępne jakby ktoś chciał się w to pobawić, a zadanie nie powinno być ponad siły studenta drugiego roku informatyki). IIRC żadna z obecnie dosŧępnych implemetacji syslogd dosŧępna na Linuxie nie jest zwątkowana. kloczek -- ----------------------------------------------------------- *Ludzie nie mają problemów, tylko sobie sami je stwarzają* ----------------------------------------------------------- Tomasz Kłoczko, sys adm @zie.pg.gda.pl|*e-mail: kloczek@rudy.mif.pg.gda.pl*