время в логах на приличной нагрузке.

[Igor Sysoev]

On Tue, Sep 09, 2008 at 05:30:22PM +0400, calculator at land.ru wrote:

> Igor Sysoev пишет:
> >On Tue, Sep 09, 2008 at 01:28:41PM +0400, calculator at land.ru wrote:
> >
> >  
> >>Igor Sysoev пишет:
> >>    
> >>>On Tue, Sep 09, 2008 at 12:44:21PM +0400, calculator at land.ru wrote:
> >>>
> >>> 
> >>>      
> >>>>Igor Sysoev пишет:
> >>>>   
> >>>>        
> >>>>>On Tue, Sep 09, 2008 at 11:18:33AM +0400, calculator at land.ru wrote:
> >>>>>
> >>>>>
> >>>>>     
> >>>>>          
> >>>>>>Igor Sysoev пишет:
> >>>>>>  
> >>>>>>       
> >>>>>>            
> >>>>>>>On Mon, Sep 08, 2008 at 07:11:59PM +0400, calculator at land.ru wrote:
> >>>>>>>
> >>>>>>>
> >>>>>>>    
> >>>>>>>         
> >>>>>>>              
> >>>>>>>>Наблюдаю интересную картину на Linux серверах с nginx на борту 
> >>>>>>>>которые отдают ~10k/s empty_gif и пишут лог кто когда забрал.
> >>>>>>>>Но вот в логе(если перелопатить его пару тонн) встречаются 
> >>>>>>>>интересные unixtime, которые явно _не к месту_. К примеру:
> >>>>>>>>
> >>>>>>>>1220880388504
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220880388496
> >>>>>>>>1220880388496
> >>>>>>>>1220880388496
> >>>>>>>>1220880388496
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220884786554
> >>>>>>>>1220880388496
> >>>>>>>>
> >>>>>>>>Если по человечески то разница получается более часа.
> >>>>>>>>Есть предположение что это может быть связано с linux threads 
> >>>>>>>>потому как на нескольких серверах под FreeBSD такого не 
> >>>>>>>>наблюдалось(хотя нагрузка на них не большая).
> >>>>>>>>На серверах nginx 5 ветки работает.
> >>>>>>>>Что касается загрузки самих серверов, то они сечас нагружены на 
> >>>>>>>>~20% от максимума что показали на тестировании.
> >>>>>>>>Есть идеи?
> >>>>>>>>
> >>>>>>>>      
> >>>>>>>>           
> >>>>>>>>                
> >>>>>>>А чем пишете ? nginx так не умеет. У него было бы
> >>>>>>>1220884786.554
> >>>>>>>1220880388.496
> >>>>>>>
> >>>>>>>    
> >>>>>>>         
> >>>>>>>              
> >>>>>>Да там модуль постобработку делает. Извиняюсь что не упомянул, но в 
> >>>>>>общем случае он порядок не меняет.
> >>>>>>Что интересно _пляски_ начинаются стабильно от ~8k запросов.
> >>>>>>Увеличение NGX_TIME_SLOTS может помочь?
> >>>>>>  
> >>>>>>       
> >>>>>>            
> >>>>>Во-первых, поддержка трэдов на данный момент в nginx'е сломана - может
> >>>>>быть всё, что угодно. Во-вторых, я в данном случае вообще не понимаю,
> >>>>>что именно логируется.
> >>>>>
> >>>>>
> >>>>>
> >>>>>     
> >>>>>          
> >>>>Ага, исправлюсь. Вот формат логов.
> >>>>
> >>>>  log_format  counter  '$request_uri  $msec   $http_referer   
> >>>>$remote_addr'
> >>>>                      '       $http_user_agent        
> >>>>$http_accept_language'
> >>>>                      '       $http_x_forwarded_for'
> >>>>                      '       $counter_uid';
> >>>>  access_log  logs/access.log  counter;
> >>>>
> >>>>
> >>>>После обработки примерно такие логи получаются:
> >>>>
> >>>>/two****request_uri     1220880388504   http_referer    78.107.87.211   
> >>>>Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; MRSPUTNIK 2, 0, 0, 
> >>>>36 SW; .NET CLR 1.1.4322; InfoPath.1)     ru      -       
> >>>>B0B903034799DD57:1201266007
> >>>>/two***request_uri      1220884786554   -       81.24.208.13    
> >>>>Mozilla/5.0 (Windows; U; Windows NT 5.1; ru; rv:1.8.1.16) 
> >>>>Gecko/20080702 Firefox/2.0.0.16 WebMoney Advisor      
> >>>>ru-ru,ru;q=0.8,en-us;q=0.5,en;q=0.3     -       -
> >>>>/two****request_uri     1220880388496   http_referer    78.132.162.209  
> >>>>Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; MRA 5.0 (build 
> >>>>02094))       ru      -       E5930201476FE72C:1198516012
> >>>>   
> >>>>        
> >>>Правильно ли я понимаю, что используется стандартный nginx без каких-либо
> >>>дополнительных изменений и из логах в $msec потом просто убирается точка 
> >>>?
> >>>
> >>> 
> >>>      
> >>Да, именно так.
> >>    
> >
> >А можно ещё писать в лог номер процесса, чтобы посмотреть, где идёт
> >отставание ?
> >  
> Да в том то и дело что нет. На боевом сервере формат логов оговорен, мы 
> их отдаем на обработку потом. Если поднапрячься наверно можно 2 сервера 
> еще собрать на тестирование но нужно будет еще код counter'а подправить.
> Еще заметили закономерность что разница во времени всегда 4398 либо 4399

Можно завести параллельно второй лог.


-- 
Игорь Сысоев
http://sysoev.ru