View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000642Apache 2.x Bugpublic2014-12-29 19:122022-02-19 21:35
ReporterSteven Levine Assigned To 
PrioritynormalSeverityminorReproducibilityalways
Status newResolutionopen 
Summary0000642: apache stops responding to simple mysql requests from ab.exe
DescriptionA stress test run as

  ab -c1 -n4000 http://slamain/hello-db.php

never completes. apache stops responding after some number of requests - typically between 500 and 3500. The failure is not permanent. If one waits a bit and retrys, apache will responds to some number of new requests before it again stops responding. It appears that whatever resource is causing the failure mode is released after some period of time.

Similar tests

  ab -c1 -n10000 http://slamain/hello.php
  ab -c1 -n10000 http://slamain/

which eliminate mysql from the processing chain run to completion.
Additional InformationA bit of experimenting with rexxtry as in:

rexxtry `l=2;s=65;do i = 1 to l;say i 'of' l 'sleeping' s;call syssleep s;'ab -dSc1 -n3000 http://slamain/hello-db.php |& tee clip:';end`

results in the 2nd pass usually completing without errors. This indicates that the mysql internal timeout for releasing the resources it is holding is something in the range of 60 seconds.

TagsNo tags attached.
Attached Files
hello-db.php (1,025 bytes)
helloi-db.php (980 bytes)

Relationships

has duplicate 0000641 closedSteven Levine MySQL v5 for OS/2 & eComStation apache server stops responding to simple requests from ab.exe 
related to 0000658 assignedSteven Levine Apache 2.x  ab.exe fails when accessing site over the WAN 

Activities

Steven Levine

2014-12-29 23:37

manager   ~0002982

Repeated

    ab -c40 -n2900 http://slamain/hello-db.php

runs without sufficient quiet time can result in:

    [Mon Dec 29 15:05:54 2014] [notice] Apache/2.2.29 (OS/2) PHP/5.4.36 configured -- resuming normal operations
    [Mon Dec 29 15:05:54 2014] [info] Server built: Dec 29 2014 07:52:35
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [debug] core.c(4023): [client 127.0.0.1] (OS 10055)No buffer space available: apr_socket_opt_set(APR_TCP_NODELAY)
    [Mon Dec 29 15:10:54 2014] [info] [client 127.0.0.1] (OS 10055)No buffer space available: core_output_filter: writing data to the network
    [Mon Dec 29 15:10:54 2014] [error] (OS 10055)No buffer space available: apr_socket_accept
    [Mon Dec 29 15:10:54 2014] [error] (OS 10055)No buffer space available: apr_socket_accept
    [Mon Dec 29 15:10:55 2014] [info] removed PID file D:/Internet/apache22/logs/httpd.pid (pid=5362)
    [Mon Dec 29 15:10:55 2014] [info] pidSemaphoreOwner = 0, tidSemaphoreOwner = 0, ulRequestCount = 0l
    [Mon Dec 29 15:10:55 2014] [notice] caught SIGTERM, shutting down

The failure in core_output_filter is not terminal, except to the transaction. It's probably a good idea to add a counted sleep and retry loop because there is no reason fail the transaction if the situation is temporary.

The apr_socket_accept failure is terminal and this is not a good thing. A counted sleep and retry loop is required. We need to figure out the best values to use for the sleep and retry limits.

psmedley

2014-12-30 20:57

administrator   ~0002983

which mysql driver is being used? mysql.dll, mysqli.dll or one of the pdo ones?

Steven Levine

2014-12-31 10:07

manager   ~0002984

Hello-db.php is using mysqli. I can always build a mysql version if needed. It occurred to me earlier today that I neglected to add a mysqli_close, which might explain the temporary out of resource issue. I'll check this tomorrow.

The code that I derived the testcase from is production code, but it's something I inherited and the code is still a bit dirty. One of the things it does not do is close the connection before returning control to the server. I guess I will fix this.

Steven Levine

2015-01-02 01:22

manager   ~0002987

Adding mysqli_close has no effect on the failure mode.

A bit more experimenting with

rexxtry `l=10;s=62;do i = 1 to l;say i 'of' l 'sleeping' s;call syssleep s;'ab -dSc1 -n2999 http://slamain/hello-db.php';end` |& tee /a tmp.out

indicates that there is some sort of 2999 item resource limit. Running the above with -n3000 always generates and error.

It also appears that the resources are help for 60 seconds after last use before they are released. Running the above with s=61 will sometimes fail, but this is probably just jitter in the thread scheduling.

These numbers give us an idea of what to look for in the mysqli extension. It is extremely unlikely that the limits are in the mysql daemon.

psmedley

2015-01-02 01:25

administrator   ~0002988

Thanks for the information. It would be interesting to know if the same problems exist with mysql. That may point to a problem with mysqlnd rather than in the specific module.

I will try have a poke around the code this afternoon - about to go pick up some Thai takeaway for lunch :)

Steven Levine

2015-01-02 02:41

manager   ~0002989

I've uploaded the mysql and mysqli versions of the testcase.

The failure modes look to be the same for both APIs.

psmedley

2015-01-02 03:48

administrator   ~0002990

Thanks for confirming. I'll poke around the mysqlnd code today/tonight.

psmedley

2015-01-02 05:03

administrator   ~0002991

I suspect the timeout setting comes from php.ini:
; Maximum time (in secondes) for connect timeout. -1 means no limit
mysql.connect_timeout = 60

psmedley

2015-01-02 05:11

administrator   ~0002992

Last edited: 2015-01-02 06:26

 I had thought that with PHP 5.4.x and above, the build in mysqlnd client *had* to be used. Looking at configure again, it appears that it is optional.

I will try and do a build now using mysqlclient that is probably better tested under OS/2 and see if that resolves this issue.

[sigh] with a build using mysqlclient I get:
Could not connect: Can't connect to local MySQL server through socket '\\socket\\MySQL' (49)

Issue History

Date Modified Username Field Change
2014-12-29 19:12 Steven Levine New Issue
2014-12-29 19:14 Steven Levine Relationship added has duplicate 0000641
2014-12-29 23:37 Steven Levine Note Added: 0002982
2014-12-30 20:57 psmedley Note Added: 0002983
2014-12-31 10:07 Steven Levine Note Added: 0002984
2015-01-02 01:22 Steven Levine Note Added: 0002987
2015-01-02 01:25 psmedley Note Added: 0002988
2015-01-02 01:26 Steven Levine File Added: hello-db.php
2015-01-02 02:38 Steven Levine File Deleted: hello-db.php
2015-01-02 02:38 Steven Levine File Added: hello-db.php
2015-01-02 02:39 Steven Levine File Added: helloi-db.php
2015-01-02 02:41 Steven Levine Note Added: 0002989
2015-01-02 03:48 psmedley Note Added: 0002990
2015-01-02 05:03 psmedley Note Added: 0002991
2015-01-02 05:11 psmedley Note Added: 0002992
2015-01-02 06:26 psmedley Note Edited: 0002992
2021-07-01 21:13 Steven Levine Project MySQL v5 for OS/2 & eComStation => Apache 2.x
2022-02-19 21:35 Steven Levine Relationship added related to 0000658