I'm running a web server with "webservice --backend=kubernetes python3.7". As I tail the uwsgi.log file, requests to my server get logged with very long delays. I just timed one at about a minute and a half between when the request was served (03:07:57 UTC 2020) and when it showed up in the log file (03:09:23 UTC 2020).
What is going on here? Is there some way to make it not do this?
My guess is output stream buffering, at either the libc level or the python level.
Which tool is this? I can probably strace and see if that is the case.
YiFei Zhu
On Wed, Jun 24, 2020 at 10:16 PM Roy Smith roy@panix.com wrote:
I'm running a web server with "webservice --backend=kubernetes python3.7". As I tail the uwsgi.log file, requests to my server get logged with very long delays. I just timed one at about a minute and a half between when the request was served (03:07:57 UTC 2020) and when it showed up in the log file (03:09:23 UTC 2020).
What is going on here? Is there some way to make it not do this? _______________________________________________ Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
https://tools.wmflabs.org/spi-tools/spi/ https://tools.wmflabs.org/spi-tools/spi/
To generate a request, click the "Sock Info" button or the "Index" link.
The log file is /data/project/spi-tools/uwsgi.log
Thanks.
On Jun 25, 2020, at 2:12 AM, YiFei Zhu zhuyifei1999@gmail.com wrote:
My guess is output stream buffering, at either the libc level or the python level.
Which tool is this? I can probably strace and see if that is the case.
YiFei Zhu
On Wed, Jun 24, 2020 at 10:16 PM Roy Smith roy@panix.com wrote:
I'm running a web server with "webservice --backend=kubernetes python3.7". As I tail the uwsgi.log file, requests to my server get logged with very long delays. I just timed one at about a minute and a half between when the request was served (03:07:57 UTC 2020) and when it showed up in the log file (03:09:23 UTC 2020).
What is going on here? Is there some way to make it not do this? _______________________________________________ Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Looks like writev syscall does happen instantly, and tail on the host that is running the uwsgi process is also returning the newly written data instantly. Tail on a bastion host seems to see seconds of delay for me, whether I use `tail -f` `tail -F` or `watch tail`. However, the delay is gone if I use `tail -f` on the uwsgi host. Looks like the kernel is buffering the data...
YiFei Zhu
On Thu, Jun 25, 2020 at 8:12 AM Roy Smith roy@panix.com wrote:
https://tools.wmflabs.org/spi-tools/spi/
To generate a request, click the "Sock Info" button or the "Index" link.
The log file is /data/project/spi-tools/uwsgi.log
Thanks.
On Jun 25, 2020, at 2:12 AM, YiFei Zhu zhuyifei1999@gmail.com wrote:
My guess is output stream buffering, at either the libc level or the python level.
Which tool is this? I can probably strace and see if that is the case.
YiFei Zhu
On Wed, Jun 24, 2020 at 10:16 PM Roy Smith roy@panix.com wrote:
I'm running a web server with "webservice --backend=kubernetes python3.7". As I tail the uwsgi.log file, requests to my server get logged with very long delays. I just timed one at about a minute and a half between when the request was served (03:07:57 UTC 2020) and when it showed up in the log file (03:09:23 UTC 2020).
What is going on here? Is there some way to make it not do this? _______________________________________________ Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Heh, my mail about NFS being involved cross paths with yours. Thanks for digging into this for me.
Should I open a phab ticket on this?
On Jun 25, 2020, at 3:50 PM, YiFei Zhu zhuyifei1999@gmail.com wrote:
Looks like writev syscall does happen instantly, and tail on the host that is running the uwsgi process is also returning the newly written data instantly. Tail on a bastion host seems to see seconds of delay for me, whether I use `tail -f` `tail -F` or `watch tail`. However, the delay is gone if I use `tail -f` on the uwsgi host. Looks like the kernel is buffering the data...
YiFei Zhu
On Thu, Jun 25, 2020 at 8:12 AM Roy Smith roy@panix.com wrote:
https://tools.wmflabs.org/spi-tools/spi/
To generate a request, click the "Sock Info" button or the "Index" link.
The log file is /data/project/spi-tools/uwsgi.log
Thanks.
On Jun 25, 2020, at 2:12 AM, YiFei Zhu zhuyifei1999@gmail.com wrote:
My guess is output stream buffering, at either the libc level or the python level.
Which tool is this? I can probably strace and see if that is the case.
YiFei Zhu
On Wed, Jun 24, 2020 at 10:16 PM Roy Smith roy@panix.com wrote:
I'm running a web server with "webservice --backend=kubernetes python3.7". As I tail the uwsgi.log file, requests to my server get logged with very long delays. I just timed one at about a minute and a half between when the request was served (03:07:57 UTC 2020) and when it showed up in the log file (03:09:23 UTC 2020).
What is going on here? Is there some way to make it not do this? _______________________________________________ Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Should I open a phab ticket on this?
Yes please.
On Thu, Jun 25, 2020 at 2:55 PM Roy Smith roy@panix.com wrote:
Heh, my mail about NFS being involved cross paths with yours. Thanks for digging into this for me.
Should I open a phab ticket on this?
On Jun 25, 2020, at 3:50 PM, YiFei Zhu zhuyifei1999@gmail.com wrote:
Looks like writev syscall does happen instantly, and tail on the host that is running the uwsgi process is also returning the newly written data instantly. Tail on a bastion host seems to see seconds of delay for me, whether I use `tail -f` `tail -F` or `watch tail`. However, the delay is gone if I use `tail -f` on the uwsgi host. Looks like the kernel is buffering the data...
YiFei Zhu
On Thu, Jun 25, 2020 at 8:12 AM Roy Smith roy@panix.com wrote:
https://tools.wmflabs.org/spi-tools/spi/
To generate a request, click the "Sock Info" button or the "Index" link.
The log file is /data/project/spi-tools/uwsgi.log
Thanks.
On Jun 25, 2020, at 2:12 AM, YiFei Zhu zhuyifei1999@gmail.com wrote:
My guess is output stream buffering, at either the libc level or the python level.
Which tool is this? I can probably strace and see if that is the case.
YiFei Zhu
On Wed, Jun 24, 2020 at 10:16 PM Roy Smith roy@panix.com wrote:
I'm running a web server with "webservice --backend=kubernetes python3.7". As I tail the uwsgi.log file, requests to my server get logged with very long delays. I just timed one at about a minute and a half between when the request was served (03:07:57 UTC 2020) and when it showed up in the log file (03:09:23 UTC 2020).
What is going on here? Is there some way to make it not do this? _______________________________________________ Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
https://phabricator.wikimedia.org/T256426 https://phabricator.wikimedia.org/T256426
On Jun 25, 2020, at 4:00 PM, YiFei Zhu zhuyifei1999@gmail.com wrote:
Should I open a phab ticket on this?
Yes please.
On Thu, Jun 25, 2020 at 2:55 PM Roy Smith roy@panix.com wrote:
Heh, my mail about NFS being involved cross paths with yours. Thanks for digging into this for me.
Should I open a phab ticket on this?
On Jun 25, 2020, at 3:50 PM, YiFei Zhu zhuyifei1999@gmail.com wrote:
Looks like writev syscall does happen instantly, and tail on the host that is running the uwsgi process is also returning the newly written data instantly. Tail on a bastion host seems to see seconds of delay for me, whether I use `tail -f` `tail -F` or `watch tail`. However, the delay is gone if I use `tail -f` on the uwsgi host. Looks like the kernel is buffering the data...
YiFei Zhu
On Thu, Jun 25, 2020 at 8:12 AM Roy Smith roy@panix.com wrote:
https://tools.wmflabs.org/spi-tools/spi/
To generate a request, click the "Sock Info" button or the "Index" link.
The log file is /data/project/spi-tools/uwsgi.log
Thanks.
On Jun 25, 2020, at 2:12 AM, YiFei Zhu zhuyifei1999@gmail.com wrote:
My guess is output stream buffering, at either the libc level or the python level.
Which tool is this? I can probably strace and see if that is the case.
YiFei Zhu
On Wed, Jun 24, 2020 at 10:16 PM Roy Smith roy@panix.com wrote:
I'm running a web server with "webservice --backend=kubernetes python3.7". As I tail the uwsgi.log file, requests to my server get logged with very long delays. I just timed one at about a minute and a half between when the request was served (03:07:57 UTC 2020) and when it showed up in the log file (03:09:23 UTC 2020).
What is going on here? Is there some way to make it not do this? _______________________________________________ Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
This seems to be related to NFS, or maybe some interaction between docker and NFS.
I set up django to do its own logging, and saw the same behavior. Next I connected to the docker node with "webservice --backend=kubernetes python3.7 shell" and append directly to the log file with "echo foo >> django.log". It still took 30 seconds or so to show up while I was tailing the file on the bastion.
On Jun 25, 2020, at 2:12 AM, YiFei Zhu zhuyifei1999@gmail.com wrote:
My guess is output stream buffering, at either the libc level or the python level.
Which tool is this? I can probably strace and see if that is the case.
YiFei Zhu
On Wed, Jun 24, 2020 at 10:16 PM Roy Smith roy@panix.com wrote:
I'm running a web server with "webservice --backend=kubernetes python3.7". As I tail the uwsgi.log file, requests to my server get logged with very long delays. I just timed one at about a minute and a half between when the request was served (03:07:57 UTC 2020) and when it showed up in the log file (03:09:23 UTC 2020).
What is going on here? Is there some way to make it not do this? _______________________________________________ Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud
Wikimedia Cloud Services mailing list Cloud@lists.wikimedia.org (formerly labs-l@lists.wikimedia.org) https://lists.wikimedia.org/mailman/listinfo/cloud