nginx-0.8.1

Thu Jun 11 21:30:13 MSD 2009

On Thu, Jun 11, 2009 at 09:18:31PM +0400, Volkov Oleg wrote:

> В Чтв, 11/06/2009 в 13:33 +0400, Igor Sysoev пишет:
> > On Wed, Jun 10, 2009 at 10:04:36PM +0400, Volkov Oleg wrote:
> > 
> > > В Срд, 10/06/2009 в 20:28 +0400, Igor Sysoev пишет:
> > > > On Wed, Jun 10, 2009 at 07:20:49PM +0400, Volkov Oleg wrote:
> > > > 
> > > > > В Срд, 10/06/2009 в 13:58 +0400, Igor Sysoev пишет:
> > > > > > On Tue, Jun 09, 2009 at 07:53:38PM +0400, Volkov Oleg wrote:
> > > > > > 
> > > > > > > > > Вот пример одного из запросов. Урл заменен на ...
> > > > > > > > > Файловая система xfs
> > > > > > > > > Замена на tmpfs не помогает
> > > > > > > > 
> > > > > > > > [...]
> > > > > > > > 
> > > > > > > > > 2009/06/09 08:27:27 [debug] 18409#0: *29739 cached open
> > > > > > > > > file: /var/tmp/nginx/proxy_cache2/7/4c/d834b44900b7d1770f6819308056b4c7,
> > > > > > > > > fd:4195, c:1, e:0, u:9
> > > > > > > > 
> > > > > > > > Отключите open_file_cache.
> > > > > > > 
> > > > > > > Максим, огромное спасибо. Заработало. 
> > > > > > > Отключил open_file_cache для проксируемых запросов и эффективность
> > > > > > > кеширования стала 99.86%.
> > > > > > > 
> > > > > > > Желательно все же подправить исходники (в будущих версиях), чтобы при
> > > > > > > изменении состояния кеша с включенной опцией open_file_cache nginx
> > > > > > > нормально работал.
> > > > > > 
> > > > > > Похоже, проблема в xfs и tmpfs. nginx сравнивает inode закэшированного
> > > > > > открытого файла и inode файла в зоне кэша. Похоже, что xfs и tmpfs вместо
> > > > > > inode возварщают ноль. Нужно смотреть, что уникально для файла в xfs,
> > > > > > tmpfs и прочих им подобных.
> > > > > 
> > > > > Могу предложить при выполнении записи в кеш (переименовании из
> > > > > временного файла) чистить нужное значение в open_file_cache.
> > > > 
> > > > Кэш общий для всех воркеров, а open_file_cache - внутри каждого воркера
> > > > свой: файловые дескрипторы у каждого свои.
> > > 
> > > Ага, это объясняет поведение nginx при количестве воркеров > 1, когда
> > > часть запросов проксировалась, а часть из кеша отдавалась. Кстати, если
> > > как-то вывести в лог номер воркера (в обычный лог, не дебаг)... А то у
> > 
> > $pid
> > 
> > > меня предположение, что ломается именно тот воркер, который и апдейтит
> > > кеш. Предположение основано на том, что у меня при 8 воркерах
> > > эффективность кеширования была порядка 80%. Поэтому предлагаю
> > > реализовать очистку open_file_cache текущего воркера, я наложу этот патч
> > > и посмотрю что выйдет.
> > > 
> > > А вообще, между воркерами есть система сигналов? Можно дать команду на
> > > очистку конкретного значения из open_file_cache всеми воркерами?
> > 
> > Сигналов пока нет. Но чистить нужно лениво по inode, а не для всех подряд.
> > 
> > > Вообще если какая либо программа откроет файл, а другая программа в него
> > > переименует второй файл, то первая программа просто не узнает об этом.
> > > Ей надо закрыть файл и открыть снова. Файл будет удален, но на диске он
> > > будет продолжать существовать, пока его не отпустит программа номер 1.
> > > 
> > > Что касаемо инод в XFS
> > > $ echo 1 >1
> > > $ echo 2 >2
> > > $ find . -printf "%p %i\n"
> > > . 100666534
> > > ./1 103771654
> > > ./2 105527833
> > > $ mv 2 1 
> > > $ find . -printf "%p %i\n"
> > > . 100666534
> > > ./1 105527833
> > > 
> > > Так что номер иноды меняется. Для tmpfs все абсолютно тоже самое.
> > 
> > Патч, исправляющий проверку inode на старте.
> 
> Патч не помог. Я наложил его и патч со статусом.
> Если я включаю open_file_cache и у меня 8 воркеров, то
> 
> 1244740011.462 0.000 200 - - HIT 29730 11/Jun/2009:21:06:51
> 1244740011.891 0.000 200 - - HIT 29721 11/Jun/2009:21:06:51
> ---
> 1244740012.557 0.107 200 0.107 200 EXPIRED 29724 11/Jun/2009:21:06:52
> 1244740012.732 0.000 200 - - HIT 29727 11/Jun/2009:21:06:52
> 1244740013.008 0.000 200 - - HIT 29722 11/Jun/2009:21:06:53
> 1244740013.913 0.000 200 - - HIT 29728 11/Jun/2009:21:06:53
> 1244740013.918 0.000 200 - - HIT 29728 11/Jun/2009:21:06:53
> 1244740014.088 0.000 200 - - HIT 29727 11/Jun/2009:21:06:54
> 1244740014.227 0.000 200 - - HIT 29727 11/Jun/2009:21:06:54
> 1244740014.422 0.084 200 0.084 200 EXPIRED 29730 11/Jun/2009:21:06:54
> 1244740014.658 0.000 200 - - HIT 29724 11/Jun/2009:21:06:54
> 1244740014.674 0.000 200 - - HIT 29724 11/Jun/2009:21:06:54
> 1244740014.677 0.000 200 - - HIT 29724 11/Jun/2009:21:06:54
> 1244740015.428 0.000 200 - - HIT 29728 11/Jun/2009:21:06:55
> 1244740016.018 0.080 200 0.080 200 EXPIRED 29730 11/Jun/2009:21:06:56
> 1244740016.163 0.000 200 - - HIT 29722 11/Jun/2009:21:06:56
> 1244740016.333 0.000 200 - - HIT 29722 11/Jun/2009:21:06:56
> 1244740016.400 0.000 200 - - HIT 29724 11/Jun/2009:21:06:56
> 1244740016.413 0.000 200 - - HIT 29724 11/Jun/2009:21:06:56
> 1244740016.902 0.000 200 - - HIT 29722 11/Jun/2009:21:06:56
> 1244740017.333 0.095 200 0.095 200 EXPIRED 29723 11/Jun/2009:21:06:57
> 1244740019.011 0.094 200 0.094 200 EXPIRED 29723 11/Jun/2009:21:06:59
> 1244740019.234 0.000 200 - - HIT 29721 11/Jun/2009:21:06:59
> 1244740019.944 0.000 200 - - HIT 29727 11/Jun/2009:21:06:59
> 1244740020.111 0.000 200 - - HIT 29727 11/Jun/2009:21:07:00
> 1244740020.159 0.000 200 - - HIT 29728 11/Jun/2009:21:07:00
> 1244740020.266 0.000 200 - - HIT 29722 11/Jun/2009:21:07:00
> 1244740020.456 0.000 200 - - HIT 29728 11/Jun/2009:21:07:00
> 1244740020.827 0.000 200 - - UPDATING 29723 11/Jun/2009:21:07:00
> 1244740020.867 0.089 200 0.089 200 EXPIRED 29723 11/Jun/2009:21:07:00
> 1244740020.952 0.000 200 - - HIT 29722 11/Jun/2009:21:07:00
> 1244740021.935 0.000 200 - - HIT 29727 11/Jun/2009:21:07:01
> 1244740022.037 0.000 200 - - HIT 29722 11/Jun/2009:21:07:02
> 1244740022.160 0.000 200 - - HIT 29724 11/Jun/2009:21:07:02
> 1244740022.243 0.000 200 - - HIT 29724 11/Jun/2009:21:07:02
> 1244740022.563 0.000 200 - - HIT 29721 11/Jun/2009:21:07:02
> 1244740024.504 0.000 200 - - HIT 29727 11/Jun/2009:21:07:04
> 1244740024.711 0.000 200 - - HIT 29729 11/Jun/2009:21:07:04
> 1244740025.055 0.000 200 - - HIT 29729 11/Jun/2009:21:07:05
> 1244740025.624 0.000 200 - - HIT 29729 11/Jun/2009:21:07:05
> 1244740026.742 0.083 200 0.083 200 EXPIRED 29723 11/Jun/2009:21:07:06
> 1244740027.924 0.000 200 - - HIT 29727 11/Jun/2009:21:07:07
> 1244740028.913 0.000 200 - - HIT 29727 11/Jun/2009:21:07:08
> 1244740029.356 0.000 200 - - HIT 29728 11/Jun/2009:21:07:09
> 1244740029.541 0.000 200 - - HIT 29724 11/Jun/2009:21:07:09
> 1244740029.866 0.000 200 - - HIT 29729 11/Jun/2009:21:07:09
> 1244740030.058 0.000 200 - - HIT 29727 11/Jun/2009:21:07:10
> 1244740030.448 0.000 200 - - HIT 29724 11/Jun/2009:21:07:10
> 1244740030.518 0.000 200 - - HIT 29724 11/Jun/2009:21:07:10
> 1244740033.208 0.089 200 0.089 200 EXPIRED 29730 11/Jun/2009:21:07:13
> 1244740033.275 0.000 200 - - HIT 29724 11/Jun/2009:21:07:13
> 1244740033.721 0.095 200 0.095 200 EXPIRED 29730 11/Jun/2009:21:07:13
> 1244740034.163 0.082 200 0.082 200 EXPIRED 29723 11/Jun/2009:21:07:14
> 1244740034.826 0.000 200 - - HIT 29722 11/Jun/2009:21:07:14
> 1244740034.847 0.000 200 - - HIT 29722 11/Jun/2009:21:07:14
> 1244740034.858 0.000 200 - - HIT 29722 11/Jun/2009:21:07:14
> 1244740034.878 0.000 200 - - HIT 29722 11/Jun/2009:21:07:14
> 1244740035.464 0.099 200 0.099 200 EXPIRED 29730 11/Jun/2009:21:07:15
> 1244740036.323 0.000 200 - - HIT 29721 11/Jun/2009:21:07:16
> 1244740036.588 0.000 200 - - HIT 29721 11/Jun/2009:21:07:16
> 1244740036.592 0.087 200 0.087 200 EXPIRED 29723 11/Jun/2009:21:07:16
> 1244740037.524 0.000 200 - - HIT 29721 11/Jun/2009:21:07:17
> 1244740037.527 0.000 200 - - HIT 29728 11/Jun/2009:21:07:17
> 1244740037.732 0.081 200 0.081 200 EXPIRED 29730 11/Jun/2009:21:07:17
> 1244740038.236 0.000 200 - - HIT 29722 11/Jun/2009:21:07:18
> 1244740038.310 0.000 200 - - HIT 29727 11/Jun/2009:21:07:18
> 1244740039.025 0.000 200 - - HIT 29721 11/Jun/2009:21:07:19
> 1244740039.108 0.000 200 - - HIT 29728 11/Jun/2009:21:07:19
> 1244740039.206 0.000 200 - - HIT 29722 11/Jun/2009:21:07:19
> 1244740039.333 0.084 200 0.084 200 EXPIRED 29730 11/Jun/2009:21:07:19
> 1244740040.169 0.000 200 - - HIT 29727 11/Jun/2009:21:07:20
> 1244740040.260 0.000 200 - - HIT 29728 11/Jun/2009:21:07:20
> 1244740040.361 0.000 200 - - HIT 29724 11/Jun/2009:21:07:20
> 1244740040.583 0.081 200 0.081 200 EXPIRED 29723 11/Jun/2009:21:07:20
> 1244740040.794 0.000 200 - - HIT 29727 11/Jun/2009:21:07:20
> 1244740040.933 0.000 200 - - HIT 29722 11/Jun/2009:21:07:20
> 1244740041.212 0.000 200 - - HIT 29728 11/Jun/2009:21:07:21
> 1244740041.979 0.000 200 - - HIT 29728 11/Jun/2009:21:07:21
> 1244740042.449 0.000 200 - - HIT 29728 11/Jun/2009:21:07:22
> 1244740042.692 0.000 200 - - HIT 29722 11/Jun/2009:21:07:22
> 1244740043.432 0.000 200 - - HIT 29721 11/Jun/2009:21:07:23
> 1244740044.625 0.000 200 - - HIT 29727 11/Jun/2009:21:07:24
> 1244740045.056 0.000 200 - - HIT 29724 11/Jun/2009:21:07:25
> 1244740046.810 0.000 200 - - HIT 29727 11/Jun/2009:21:07:26
> 1244740046.840 0.000 200 - - HIT 29728 11/Jun/2009:21:07:26
> 1244740047.326 0.000 200 - - HIT 29728 11/Jun/2009:21:07:27
> 1244740047.817 0.000 200 - - HIT 29721 11/Jun/2009:21:07:27
> 1244740048.356 0.000 200 - - HIT 29728 11/Jun/2009:21:07:28
> 1244740048.639 0.000 200 - - HIT 29728 11/Jun/2009:21:07:28
> 1244740048.661 0.000 200 - - HIT 29728 11/Jun/2009:21:07:28
> 1244740048.891 0.000 200 - - HIT 29724 11/Jun/2009:21:07:28
> 1244740049.518 0.000 200 - - HIT 29728 11/Jun/2009:21:07:29
> 1244740049.526 0.000 200 - - HIT 29727 11/Jun/2009:21:07:29
> 1244740049.975 0.000 200 - - HIT 29724 11/Jun/2009:21:07:29
> 1244740050.088 0.000 200 - - HIT 29724 11/Jun/2009:21:07:30
> 1244740051.023 0.088 200 0.088 200 EXPIRED 29730 11/Jun/2009:21:07:31
> 1244740051.320 0.104 200 0.104 200 EXPIRED 29723 11/Jun/2009:21:07:31
> 1244740051.371 0.000 200 - - HIT 29722 11/Jun/2009:21:07:31
> 1244740051.514 0.000 200 - - HIT 29728 11/Jun/2009:21:07:31
> 1244740052.802 0.093 200 0.093 200 EXPIRED 29730 11/Jun/2009:21:07:32
> 1244740053.317 0.000 200 - - HIT 29724 11/Jun/2009:21:07:33
> 1244740053.744 0.000 200 - - HIT 29729 11/Jun/2009:21:07:33
> 1244740053.866 0.000 200 - - HIT 29722 11/Jun/2009:21:07:33
> 1244740054.809 0.000 200 - - HIT 29724 11/Jun/2009:21:07:34
> 1244740054.963 0.094 200 0.094 200 EXPIRED 29723 11/Jun/2009:21:07:34
> 1244740056.622 0.000 200 - - HIT 29722 11/Jun/2009:21:07:36
> 1244740057.007 0.000 200 - - HIT 29727 11/Jun/2009:21:07:37
> 1244740057.640 0.097 200 0.097 200 EXPIRED 29723 11/Jun/2009:21:07:37
> 1244740058.161 0.000 200 - - HIT 29722 11/Jun/2009:21:07:38
> 1244740059.338 0.081 200 0.081 200 EXPIRED 29723 11/Jun/2009:21:07:39
> 1244740059.678 0.087 200 0.087 200 EXPIRED 29730 11/Jun/2009:21:07:39
> 1244740059.717 0.000 200 - - HIT 29724 11/Jun/2009:21:07:39
> 1244740059.783 0.000 200 - - HIT 29724 11/Jun/2009:21:07:39
> 1244740059.791 0.000 200 - - HIT 29724 11/Jun/2009:21:07:39
> 1244740059.901 0.000 200 - - HIT 29721 11/Jun/2009:21:07:39
> 1244740059.909 0.000 200 - - HIT 29721 11/Jun/2009:21:07:39
> 1244740060.598 0.000 200 - - HIT 29722 11/Jun/2009:21:07:40
> 1244740060.966 0.000 200 - - HIT 29722 11/Jun/2009:21:07:40
> 1244740060.993 0.000 200 - - HIT 29727 11/Jun/2009:21:07:40
> 1244740061.111 0.000 200 - - HIT 29721 11/Jun/2009:21:07:41
> 1244740061.647 0.000 200 - - HIT 29727 11/Jun/2009:21:07:41
> 1244740062.002 0.000 200 - - HIT 29724 11/Jun/2009:21:07:42
> 1244740062.153 0.000 200 - - HIT 29724 11/Jun/2009:21:07:42
> 1244740062.496 0.000 200 - - HIT 29728 11/Jun/2009:21:07:42
> 1244740062.660 0.000 200 - - HIT 29728 11/Jun/2009:21:07:42
> 1244740062.678 0.085 200 0.085 200 EXPIRED 29730 11/Jun/2009:21:07:42
> ...
> 
> Если 1 воркер
> 1244740450.972 0.000 200 - - HIT 3164 11/Jun/2009:21:14:10
> 1244740450.974 0.000 200 - - HIT 3164 11/Jun/2009:21:14:10
> ---
> 1244740452.202 0.098 200 0.098 200 EXPIRED 3164 11/Jun/2009:21:14:12
> 1244740452.295 0.000 200 - - UPDATING 3164 11/Jun/2009:21:14:12
> 1244740452.301 0.000 200 - - UPDATING 3164 11/Jun/2009:21:14:12
> 1244740452.305 0.000 200 - - UPDATING 3164 11/Jun/2009:21:14:12
> 1244740452.363 0.000 200 - - UPDATING 3164 11/Jun/2009:21:14:12
> 1244740452.392 0.099 200 0.099 200 EXPIRED 3164 11/Jun/2009:21:14:12
> 1244740452.538 0.128 200 0.128 200 EXPIRED 3164 11/Jun/2009:21:14:12
> 1244740452.894 0.096 200 0.096 200 EXPIRED 3164 11/Jun/2009:21:14:12
> 1244740453.177 0.143 200 0.143 200 EXPIRED 3164 11/Jun/2009:21:14:13
> 1244740453.346 0.083 200 0.083 200 EXPIRED 3164 11/Jun/2009:21:14:13
> 1244740453.408 0.000 200 - - UPDATING 3164 11/Jun/2009:21:14:13
> 1244740453.492 0.108 200 0.108 200 EXPIRED 3164 11/Jun/2009:21:14:13
> 1244740455.787 0.152 200 0.152 200 EXPIRED 3164 11/Jun/2009:21:14:15
> 1244740456.937 0.230 200 0.230 200 EXPIRED 3164 11/Jun/2009:21:14:16
> 1244740459.111 0.344 200 0.344 200 EXPIRED 3164 11/Jun/2009:21:14:19
> 1244740459.314 0.144 200 0.144 200 EXPIRED 3164 11/Jun/2009:21:14:19
> 1244740459.541 0.000 200 - - UPDATING 3164 11/Jun/2009:21:14:19
> 1244740459.572 0.000 304 - - UPDATING 3164 11/Jun/2009:21:14:19
> 1244740459.680 0.142 200 0.142 200 EXPIRED 3164 11/Jun/2009:21:14:19
> 1244740460.420 0.000 200 - - UPDATING 3164 11/Jun/2009:21:14:20
> ...

В новом патче в режиме отладки ещё пишется inode, можно сделать отладочный
лог ?

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