big difference between request time and upstreams time

[Руслан Закиров]

Hello,

Some selected log records:
14:27:46 1.609 [0.013] [0.002] [192.168.1.44:5002]
14:27:50 1.017 [0.017] [0.001] [192.168.1.24:9000]
14:27:51 1.522 [0.021] [0.000] [192.168.1.92:9000]
14:27:50 1.019 [0.019] [0.000] [192.168.1.41:9000]
14:27:52 1.019 [0.018] [0.000] [192.168.1.49:9000]
14:27:52 1.019 [0.018] [0.001] [192.168.1.59:9000]
14:27:55 1.515 [0.014] [0.000] [192.168.1.92:9000]
14:27:57 0.510 [0.010] [0.001] [192.168.1.21:9000]
14:28:03 1.521 [0.021] [0.001] [192.168.1.48:9000]
14:28:04 0.660 [0.007] [0.002] [192.168.1.24:5002]
14:28:05 2.216 [0.018] [0.002] [192.168.1.44:5002]
14:28:11 0.510 [0.010] [0.000] [192.168.1.49:9000]
14:28:26 0.937 [0.008] [0.002] [192.168.1.92:5002]
14:28:28 1.019 [0.019] [0.000] [192.168.1.49:9000]
14:28:28 0.508 [0.007] [0.000] [192.168.1.42:9000]
14:28:31 1.021 [0.019] [0.000] [192.168.1.44:9000]
14:28:32 0.509 [0.008] [0.000] [192.168.1.48:9000]
14:28:36 1.015 [0.015] [0.000] [192.168.1.43:9000]
14:28:39 0.358 [0.007] [0.001] [192.168.1.92:5002]

columns: wallclock time, request time, upstream_request_time,
upstream_connect_time, upstream.

Please, help me diagnose this problem further as I stuck. This is subset
where request_time 50x bigger than upstream_request_time (just to make
subset less noisy). I see request times up to 60 seconds. Can not tie it to
some periodicity. It happens so often that don't see anything helpful in
strace... I stuck... Any ideas?

This is nginx/1.10.2 on FreeBSD 10.3-RELEASE-p7.

-- 
Руслан Закиров
Руководитель отдела разработки веб-сервисов
+7(916) 597-92-69, ruz @  <http://www.sports.ru/>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20180508/009fb9dc/attachment.html>