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

["calculator@xxxxxxx" <calculator@xxxxxxx>]

Igor Sysoev пишет:
> On Tue, Sep 09, 2008 at 05:30:22PM +0400, calculator@xxxxxxx wrote:
>
>   
> > Igor Sysoev пишет:
> >     
> > > On Tue, Sep 09, 2008 at 01:28:41PM +0400, calculator@xxxxxxx wrote:
> > >
> > >  
> > >       
> > > > Igor Sysoev пишет:
> > > >    
> > > >         
> > > > > On Tue, Sep 09, 2008 at 12:44:21PM +0400, calculator@xxxxxxx wrote:
> > > > >
> > > > >
> > > > >      
> > > > >           
> > > > > > Igor Sysoev пишет:
> > > > > >   
> > > > > >        
> > > > > >             
> > > > > > > On Tue, Sep 09, 2008 at 11:18:33AM +0400, calculator@xxxxxxx wrote:
> > > > > > >
> > > > > > >
> > > > > > >     
> > > > > > >          
> > > > > > >               
> > > > > > > > Igor Sysoev пишет:
> > > > > > > >  
> > > > > > > >       
> > > > > > > >            
> > > > > > > >                 
> > > > > > > > > On Mon, Sep 08, 2008 at 07:11:59PM +0400, calculator@xxxxxxx 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
> >     
> Можно завести параллельно второй лог.
>
>
>   
Да, похоже во время больших нагрузок так и сделаем.
Но похоже нам придется немного код nginx'а дополнить чтобы pid в логи 
писать или я ошибаюсь?