Periodic HTTP request delays, stoppage about hyperfastcgi

[xplicit]

Do you get timeout for every request or some requests are served and some get delays? And some additional information is reqired:

• OS version, mono --version (and how mono was installed from OS repo/Xamarin repo/or compiled from sources)
• configs of hyperfastcgi and nginx
• nginx logs in debug mode.
• hyperfastcgi logs.

Also, it would be useful to know if ab -n 100 -c 1 works or not and can the page be accessed via browser. If "ab -n 10000 -c 1" works, can you check with different multithreading options in hyperfastcgi config (use Single instead of ThreadPool in <multithreading> element of transport config)

I have not got such delays before, only when keepalive option was misconfigured between nginx and hyperfastcgi, but this was resolved in hfc v0.4 and should not produce such issues.

[bataras]

I have been able to reproduce this more easily. I modified the HelloRequest class to simulate random CPU consumption like a real web page/api will...

    public class HelloWorldRequest : BaseRawRequest
    {
        Random rnd = new Random();
        public override void Process(IWebResponse response)
        {
            int tot = rnd.Next(1000000);
            int i = 0;
            for (i = 0; i < tot; i++)
            {
            }
            //response.Send(Encoding.ASCII.GetBytes(TestResponse.Header));
            Status = 200;
            StatusDescription = "OK";
            ResponseHeaders.Add("Content-Type", "text/html; charset=utf-8");
            response.Send(Encoding.ASCII.GetBytes(TestResponse.Response + " " + i));
            response.CompleteResponse();
        }
    }
}

Here is nginx conf.d/default...

upstream fastcgi_backend {
    server 127.0.0.1:9000;
#    server unix:/tmp/fastcgi.socket;
#    keepalive 32;
}

server {
    listen 80 default_server;
    root /var/www;
#    index index.html;

    location / {
        fastcgi_index /;
        #fastcgi_pass 127.0.0.1:9000;
        #fastcgi_pass unix:/tmp/fastcgi.socket;
#       fastcgi_keep_conn on;
        fastcgi_pass fastcgi_backend;

        include /etc/nginx/fastcgi_params;
    }
}

Here is HFC config file....

<configuration>
        <server type="HyperFastCgi.ApplicationServers.SimpleApplicationServer">
                <!-- Host factory defines how host will be created. SystemWebHostFactory creates host in AppDomain in standard ASP.NET way -->
                <host-factory>HyperFastCgi.HostFactories.SystemWebHostFactory</host-factory>
                <!-- <threads> creates threads at startup. Value "0" means default value -->
                <threads min-worker="200" max-worker="400" min-io="200" max-io="400" />
                <!--- Sets the application host root directory -->
                <!-- <root-dir>/path/to/your/dir</root-dir> -->
        </server>

        <listener type="HyperFastCgi.Listeners.NativeListener">
                <apphost-transport type="HyperFastCgi.Transports.NativeTransport"></apphost-transport>
            <protocol>InterNetwork</protocol>
            <address>127.0.0.1</address>
            <port>9000</port>
        </listener>

    <apphost type="HyperFastCgi.AppHosts.Raw.RawHost">
                <log level="Standard" write-to-console="true" />
                <add-trailing-slash>false</add-trailing-slash>
                <request-type>HyperFastCgi.AppHosts.Raw.HelloWorldRequest</request-type>
    </apphost>
</configuration>

Here is ab command....

~$ ab -n 100000 -c 1 -s 5 http://10.2.1.62/hello.aspx
This is ApacheBench, Version 2.3 <$Revision: 1528965 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 10.2.1.62 (be patient)
Completed 10000 requests
apr_pollset_poll: The timeout specified has expired (70007)
Total of 15428 requests completed

What appears to happen is the connection to nginx is successful, but it is never consumed by HFC libev. When I see a delay in requests happening (I can see CPU go to 0% on target), I can still curl hello.aspx. So it seems to only affect the connection in progress and not new connections/requests

[bataras]

OS is Ubuntu 14.04
Mon version 3.8.0
HyperFastCgi.exe 0.4.4.0 (I git cloned)

getting logs..

[bataras]

ab output...

~$ ab -n 100000 -c 1 -s 5 http://10.2.1.62/hello.aspx
This is ApacheBench, Version 2.3 <$Revision: 1528965 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 10.2.1.62 (be patient)
Completed 10000 requests
Completed 20000 requests
apr_pollset_poll: The timeout specified has expired (70007)
Total of 26001 requests completed


hfc output


~# /usr/bin/hyperfastcgi4 /appconfigdir /etc/mono-fastcgi /logfile=/var/log/mono/fastcgi.log /config hyperfastcgi-aspnet.config /printlog=True /loglevels=Debug
[2014-09-21 01:18:58Z] Debug   HyperFastCgi
[2014-09-21 01:18:58Z] Debug   Threadpool minw=200,minio=200,maxw=400,maxio=400
[2014-09-21 01:18:58Z] Debug   Root directory: /root
host-list.c:38: register_host():        *:80:/:/var/www host=0x7fcb6a7b8b58 pinned_host=0x7fcb6a7b8b58 domain=0x11ac0b0
[2014-09-21 01:18:58Z] Debug   Listening on port: 9000
[2014-09-21 01:18:58Z] Debug   Listening on address: 127.0.0.1
libev.c:461: Listen():  libevent version: 2.0.21-stable
libev.c:475: Listen():  libevent is using epoll for events.


Here is gist of last 2 requests from nginx debug log...

https://gist.github.com/bataras/93c178a270022ea30345

[bataras]

Looking at the end of nginx debug below, It looks like nginx was unable to read from upstream and then 5 seconds later, ab timeout closes the connection to nginx (ab was run with -s 5)

Server: nginx/1.4.6 (Ubuntu)
Date: Sun, 21 Sep 2014 01:20:27 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 28
Connection: close

2014/09/21 01:20:27 [debug] 20578#0: *52005 write new buf t:1 f:0 0000000000833720, pos 0000000000833720, size: 165 file: 0, size:
 0
2014/09/21 01:20:27 [debug] 20578#0: *52005 http write filter: l:0 f:0 s:165
2014/09/21 01:20:27 [debug] 20578#0: *52005 http cacheable: 0
2014/09/21 01:20:27 [debug] 20578#0: *52005 http upstream process upstream
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe read upstream: 1
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe preread: 52
2014/09/21 01:20:27 [debug] 20578#0: *52005 readv: 1:3958
2014/09/21 01:20:27 [debug] 20578#0: *52005 readv() not ready (11: Resource temporarily unavailable)
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe recv chain: -2
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe buf free s:0 t:1 f:0 0000000000833C30, pos 0000000000833C86, size: 52 file: 0, si
ze: 0
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe length: -1
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe write downstream: 1
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe write busy: 0
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe write: out:0000000000000000, f:0
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe read upstream: 0
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe buf free s:0 t:1 f:0 0000000000833C30, pos 0000000000833C86, size: 52 file: 0, si
ze: 0
2014/09/21 01:20:27 [debug] 20578#0: *52005 pipe length: -1
2014/09/21 01:20:27 [debug] 20578#0: *52005 event timer: 13, old: 1411262487711, new: 1411262487712
2014/09/21 01:20:32 [debug] 20578#0: *52005 post event 000000000085D080
2014/09/21 01:20:32 [debug] 20578#0: *52005 post event 0000000000870890
2014/09/21 01:20:32 [debug] 20578#0: *52005 delete posted event 0000000000870890
2014/09/21 01:20:32 [debug] 20578#0: *52005 http run request: "/hello.aspx?"
2014/09/21 01:20:32 [debug] 20578#0: *52005 http upstream process downstream
2014/09/21 01:20:32 [debug] 20578#0: *52005 pipe write downstream: 1

[xplicit]

I try to reproduce the issue, in Ubuntu 12.04/mono 3.8.0 your sample with RawHost works well, I don't get timeouts. I want to make exactly the same environment to test, so I need the output of
mono --version, and need to know which version of Ubuntu 14.04 is used 32 bit or 64 bit. Also, how much cores your instance has got.

And could you make test with <multithreading>Single</multithreading> option. Does this issue exis or not?

<listener type="HyperFastCgi.Listeners.NativeListener">
    <apphost-transport type="HyperFastCgi.Transports.NativeTransport">
    <multithreading>Single</multithreading>
    </apphost-transport>
    <protocol>InterNetwork</protocol>
    <address>127.0.0.1</address>
    <port>9000</port>
</listener>

[bataras]

The problem goes away I add Single

If I don't use Single then running ab with
-c 1 eventually shows the problem.

here is output from mono --version

Mono JIT compiler version 3.8.0 (tarball Thu Sep 4 12:22:04 UTC 2014)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors.
www.mono-project.com TLS: __thread SIGSEGV: altstack Notifications: epoll
Architecture: amd64 Disabled: none Misc: softdebug LLVM: supported, not
enabled. GC: sgen

I installed mono by...

wget http://download.mono-project.com/repo/xamarin.gpg apt-key add
xamarin.gpg echo "deb http://download.mono-project.com/repo/debian wheezy
main" > /etc/apt/sources.list.d/mono-xamarin.list apt-get update apt-get
dist-upgrade -y apt-get install -y mono-complete

The server is running on EC2 us-west region with this AMI...

Ubuntu Server 14.04 LTS (HVM), SSD Volume Type - ami-e7b8c0d7

It's running on c3.xlarge instance type which has 4 VCPU (
http://aws.amazon.com/ec2/instance-types/)

On Sun, Sep 21, 2014 at 5:33 AM, Sergey Zhukov [email protected]
wrote:

I try to reproduce the issue, in Ubuntu 12.04/mono 3.8.0 your sample with
RawHost works well, I don't get timeouts. I want to make exactly the same
environment to test, so I need the output of
mono --version, and need to know which version of Ubuntu 14.04 is used 32
bit or 64 bit. Also, how much cores your instance has got.

And could you make test with Single
option. Does this issue exis or not?

Single InterNetwork 127.0.0.1 9000

—
Reply to this email directly or view it on GitHub
#17 (comment).

[xplicit]

I can't reproduce it on Ubuntu 14.04 64bit too. I made fresh VPS server on DigitalOcean, installed mono 3.8.0 from official Xamarin repository, changed RawHost "Hello, World" sample with your changes, compiled and ran HyperFastCgi and ab with your parameters.
All requests were served, with no timeouts. I have several ideas, what should you look at.

1. Compare mono versions. I have this one

Mono JIT compiler version 3.8.0 (tarball Thu Sep  4 12:22:04 UTC 2014)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
TLS:           __thread
SIGSEGV:       altstack
Notifications: epoll
Architecture:  amd64
Disabled:      none
Misc:          softdebug 
LLVM:          supported, not enabled.
GC:            sgen

1. Run ab from the same computer (if you ran the test from another amazon instance). If there are no timeouts, then the issue in connection between amazon instances. (If you run ab -c 5 you will see the traffic between machines even if web page in one request was not received by ab previously, because other ab threads are still working. In the nginx log error (if exists) should be located not at the end but somewhere higher).
2. There could be a influence of huge debug messaging of HyperFastCgi libev.c:331: cmd_error(): Remote host on fd 15 timed out. in non-KeepAlive mode. These messages are not errors by their meaning, but hfc writes it too often on the screen in non-KeepAlive mode. To minimize this output uncomment keepalive 32; and fastcgi_keep_conn on in nginx config.

[xplicit]

I have not seen your comment before posted my one. If the problem is related with ThreadPool, I would not be able to test it in DigitalOcean, because the host has only 1 processor. On the 2-cores physical machine with Ubuntu 12.04 I don't have the issue, so currently don't know how to reproduce it.

[xplicit]

You can also try to use Task instead of Single in multithreading option. This enables multithreading, but uses TPL library instead of ThreadPool

[xplicit]

Could you check the latest commit? I removed some legacy racy code.

[bataras]

Cool.I will soon
On Sep 21, 2014 4:58 PM, "Sergey Zhukov" [email protected] wrote:

Could you check the latest commit? I removed some legacy racy code.

—
Reply to this email directly or view it on GitHub
#17 (comment).

[bataras]

it is still happening.

also, you may want to move the call to g_hash_table_insert in add_cmdsocket
inside the mutex.

I see you have another checkin. I'll try that too..

On Sun, Sep 21, 2014 at 6:02 PM, Bill Ataras [email protected] wrote:

Cool.I will soon
On Sep 21, 2014 4:58 PM, "Sergey Zhukov" [email protected] wrote:

Could you check the latest commit? I removed some legacy racy code.

—
Reply to this email directly or view it on GitHub
#17 (comment)
.

[bataras]

The last commit 4f4434a did not fix it.

On Sun, Sep 21, 2014 at 8:31 PM, Bill Ataras [email protected] wrote:

it is still happening.

also, you may want to move the call to g_hash_table_insert in
add_cmdsocket inside the mutex.

I see you have another checkin. I'll try that too..

On Sun, Sep 21, 2014 at 6:02 PM, Bill Ataras [email protected] wrote:

Cool.I will soon
On Sep 21, 2014 4:58 PM, "Sergey Zhukov" [email protected]
wrote:

Could you check the latest commit? I removed some legacy racy code.

—
Reply to this email directly or view it on GitHub
#17 (comment)
.

[bataras]

I am testing with a server running quad core ubuntu 14.04 and another
computer running ab. the network between them is internal in amazon and
very stable. ping time is 0.3ms between the servers.

On Sun, Sep 21, 2014 at 11:28 AM, Sergey Zhukov [email protected]
wrote:

I have not see your comment before posted my one. If the problem is
related with ThreadPool, I would not be able to test it in DigitalOcean,
because the host has only 1 processor. On the 2-cores physical machine with
Ubuntu 12.04 I don't have the issue, so currently don't know how to
reproduce it.

—
Reply to this email directly or view it on GitHub
#17 (comment).

[xplicit]

You're right about add_cmdsocket. I fixed this in 1768043 and fixed one more possible racy place. Also I've added some debug messages to notify if request tries to write response data to wrong socket. At least this should help to localize the issue, if not fixed it.

[bataras]

I had already tried these changes on my own locally and they didn't fix the
issue.

In the case of process_record, I had moved the -whole- manipulation of req
inside the mutex for safety as I don't completely understand the code.

Also for cmd_socket, this is the code I used...

static void add_cmdsocket(struct cmdsocket cmdsocket)
{
struct cmdsocket prev;

pthread_mutex_lock(&sockets_lock);
prev = g_hash_table_lookup(sockets, GINT_TO_POINTER(cmdsocket->fd));
g_hash_table_insert(sockets, GINT_TO_POINTER(cmdsocket->fd), cmdsocket);
pthread_mutex_unlock(&sockets_lock);

if (prev) {
    ERROR_OUT("Trying to add existing socket %i",cmdsocket->fd);
    //TODO: close the socket (previous or new one) and free resources
}

}

I also experimented with the order of bufferevent_enable/setcb, getoutput
and get_length in flush_cmdsocket(). None of those tests fixed the problem
either. I've been reading through the code, keeping in mind that it is
running on multiple cores in a highly parallel environment. Any state
change to a socket or buffer may not persist between 2 consecutive lines of
code.

On Sun, Sep 21, 2014 at 11:17 PM, Sergey Zhukov [email protected]
wrote:

You're right about add_cmdsocket. I fixed this and fixed one more
possible racy place. Also I've added some debug messages to notify if
request tries to write response data to wrong socket. At least this should
help to localize the issue, if not fixed it.

—
Reply to this email directly or view it on GitHub
#17 (comment).

[xplicit]

The bad thing, that I can't reproduce it in my environment. If I could do this I would be able to understand what is the cause of this behaviour and then make a fix. Without reproducing I am just guessing and trying to fix the hfc code, while the error could be in libevent or in mono threadpool or somewhere else.

[bataras]

Yeah I understand. You have tried with multi core in digital ocean? Maybe
their multi core is different from ec2?
On Sep 22, 2014 4:01 PM, "Sergey Zhukov" [email protected] wrote:

The bad thing, that I can't reproduce it in my environment. If I could do
this I would be able to understand what is the cause of this behaviour and
then make a fix. Without reproducing I am just guessing and trying to fix
the hfc code, while the error could be in libevent or in mono threadpool or
somewhere else.

—
Reply to this email directly or view it on GitHub
#17 (comment).

[xplicit]

In Digital Ocean I've got VPS only with one core. My physical machine has two cores.

[bataras]

I can give you access to a couple of ec2 instances to test on. I'll send
you an email. Ok?
On Sep 22, 2014 8:17 PM, "Sergey Zhukov" [email protected] wrote:

In Digital Ocean I've got VPS only with one core. My physical machine has
two cores.

—
Reply to this email directly or view it on GitHub
#17 (comment).

[xplicit]

If you can provide Amazon instance it would be a good chance to fix the issue. I need the fresh install of Ubuntu 14.04 to reproduce the issue. Please write info to [email protected]