High number of "worker threads not created" and "overflowed work requests"

[Thias]

Hi,

I'm using varnish svn trunk on RHEL4 x86, and after about 5 minutes of sending it quite heavy traffic, things stop working so well and web pages become slow to load... here is what varnishstat reports :

       10231        72.87        25.84 Client connections accepted
       64017        83.85       161.66 Client requests received
       46904        76.86       118.44 Cache hits
         115         0.00         0.29 Cache hits for pass
       16998         6.99        42.92 Cache misses
       17113         6.99        43.21 Backend connections success
           0         0.00         0.00 Backend connections failures
       16808         6.99        42.44 Backend connections reuses
       16823         6.99        42.48 Backend connections recycles
          17         0.00         0.04 Backend connections unused
        1187         2.00         3.00 N struct srcaddr
         220         1.00         0.56 N active struct srcaddr
         811         0.00         2.05 N struct sess_mem
         810         0.00         2.05 N struct sess
       17087         5.99        43.15 N struct object
       17086         5.99        43.15 N struct objecthead
       16955         6.99        42.82 N struct smf
           0         0.00         0.00 N small free smf
           3         0.00         0.01 N large free smf
          33         0.00         0.08 N struct vbe_conn
          93         0.00         0.23 N worker threads
          93         0.00         0.23 N worker threads created
       17205        65.88        43.45 N worker threads not created
           0         0.00         0.00 N worker threads limited
         632       -17.97         1.60 N queued work requests
       17298        65.88        43.68 N overflowed work requests
           0         0.00         0.00 N dropped work requests
           0         0.00         0.00 N expired objects
           0         0.00         0.00 N objects on deathrow
           0         0.00         0.00 HTTP header overflows
       26223        39.93        66.22 Objects sent with sendfile
       24092        23.96        60.84 Objects sent with write
        9355        27.95        23.62 Total Sessions
       63925        83.85       161.43 Total Requests
           0         0.00         0.00 Total pipe
         154         0.00         0.39 Total pass
       16948         5.99        42.80 Total fetch
    14946171     19597.00     37742.86 Total header bytes
  1625794755   2061759.36   4105542.31 Total body bytes
        1295        11.98         3.27 Session Closed
         265         0.00         0.67 Session Pipeline
          84         0.00         0.21 Session Read Ahead
       62339        71.87       157.42 Session herd
     2656226      3013.46      6707.64 SHM records
      129721       282.48       327.58 SHM writes
         127         1.00         0.32 SHM MTX contention

The "worker threads not created" and "overflowed work requests" start growing a lot when the problem appears. After switching away the traffic, but keeping varnishd running, things settle again and those values no longer grow, and things work fine again.

Right now, even though things work fine (with no real/high traffic), varnishlog reports :

    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"
    7 Debug          "Accept failed errno=24"

...and so on, LOTS of those, which seem to be "too many open files". If this is the issue, could we have a varnish command line option to have it increase the maximum number of allowed open files for itself? (possible when run as root) For now, I'll add "ulimit -n 500000" to /etc/rc.d/init.d/varnish and hope it'll fix it.

[Thias]

Right now, varnishlog reports some :

    0 Debug          "Create worker thread failed 12 Cannot allocate memory"
    0 Debug          "Create worker thread failed 12 Cannot allocate memory"
    0 Debug          "Create worker thread failed 12 Cannot allocate memory"
    0 Debug          "Create worker thread failed 12 Cannot allocate memory"

which I have no idea how to fix. The varnishd process only uses about 300MB of RAM (RSS reported by top) and the cache file on disk is 2GB (32bit x86).

[phk]

If you are running in 32bit mode and using a 2GB storage file, then there is very little virtual addressing room left for varnish to operate in.

It sounds to me like your system in general are not dimensioned for the load you are trying to put on it.

Switching to 64bit OS on the same hardware may solve the problem.

Poul-Henning

[Thias]

Unfortunately, this is a 32bit server, so switching to a 64bit OS isn't an option. It is a dual HT Xeon ("only" 512k cache per processor) with 2GB RAM and 10k rpm 36G SCSI disks, and outputting ~70Mbps with varnish makes the load reach about... 0.5... so it should be able to handle quite a lot more.

Could varnish be easily recompiled with large file support? E.g. adding -D_FILE_OFFSET_BITS=64 to the CFLAGS? RHEL4's Linux 2.6.9 can definitely support files larger than 2GB, I've actually created a 4GB file for varnish to use, but it couldn't and said :

Error: (-sfile) "/var/lib/varnish/varnish_storage.bin"
does not exist and could not be created

See for instance :  http://www.suse.de/~aj/linux_lfs.html

[phk]

No,

Varnish uses VM mapping of the storage file, so there is no way to support more than the operating systems leaves for userland processes. (between 2.5 and 3.5 GB on a 32bit system).

The amount of RAM is not important in this respect.

Are you sure your XEON's don't support 64bit mode ?

Poul-Henning

[Thias]

I'm unfortunately positive that these Xeons don't support EM64T.

So there will be a "low" limit size for the storage file, I'm fine with that as around 2GB should be enough for what I intend to do. But then how can I reliably run varnish? I got those "Cannot allocate memory" errors using a 2GB file. Should I use a smaller file? Shouldn't varnish handle the memory limit it hits a bit more gracefully?

Thanks for all your answers!

[phk]

Hmm, that's too bad.

Yes, the way to go is to try with a smaller storage file. Basically the storage file is mapped into virtual memory, so whatever size it has is not available for threads, libraries, and other allocated memory.

This is a non-issue on 64bit machines, but on 32bit machines once you start talking gigabytes, things get tight very fast.

I would probably start with .5 or 1 GB of storage and see how things develops from there.

Poul-Henning

[Thias]

Just tried a 1GB file, and get some "Cannot allocate memory" messages after a few seconds of sending real traffic. FYI, here are the sizes "top" reports for varnishd :

  PID USER PR NI  VIRT  RES  SHR S %CPU %MEM  TIME+  COMMAND            
13149 root 16  0 3042m 258m 239m S    0 12.8 0:00.00 varnishd

I'll try with a 512M file now... :-/

[Thias]

No luck. Even with a 512MB file, I still get the errors after a while. Now top reports :

  PID USER PR NI  VIRT  RES  SHR S %CPU %MEM  TIME+  COMMAND
14047 root 16  0 3030m 335m 308m S    0 16.6 0:00.00 varnishd

Seems like in all cases, the "VIRT" size manages to reach 3G (is this normal?), and things start going wrong from there on.

[des]

It looks to me like you're still running with a 2 GB file. Check your command-line parameters, and check what varnishd says about the storage file when it starts.

[phk]

It really depends on the traffic Varnish receives, but 3G is nothing out of the ordinary.

The other side of this is that a failure to create a workerthread is not necessarily a bad thing in Varnish. The request will just be queued for when another workerthread becomes available.

Check with varnishstat(1) how many threads it manages to create, and check with varnishhist(1) what your response time looks like. As long as your responsetime is fine, it doesn't matter of some requests are a bit slow.

On the other hand, if you have many slow clients and large objects, you will tie up a lot of worker threads, and there is no way around it in Varnish. (... right now. I have been thinking of ways to address that, but nothing sensible has presented itself yet).

If you're trying to put varnish in front of a really heavy web-service, 64 bit is probably the only way to get the necessary space for both storage and worker threads.

Poul-Henning

[Thias]

Well, /var/log/messages seems to indicate that it's using the right file :

Feb 16 13:11:30 content07 varnishd: pclose=0
Feb 16 13:11:30 content07 varnishd: file /var/lib/varnish/varnish_storage.bin
 size 536870912 bytes (131072 fs-blocks, 131072 pages)
Feb 16 13:11:30 content07 varnishd: Using old SHMFILE
Feb 16 13:11:30 content07 varnish: varnishd startup succeeded

This is a file I've pre-created with dd, and after checking, its size is still 512M (in case varnish would try and make it grow or something). The command-line parameter I'm passing at the moment is plain "-s file,/var/lib/varnish/varnish_storage.bin" without the size, so that it uses the existing file as-is, which is seems to be doing.

Right now, I'm pushing about 90Mbps, with no problem (yet), thus here are the workers :

         233         0.00         0.25 N worker threads
         331         0.00         0.36 N worker threads created
           0         0.00         0.00 N worker threads not created

Oh, errors started to appear now :

         244         0.00         0.24 N worker threads
         342         0.00         0.34 N worker threads created
         434         0.00         0.43 N worker threads not created

I don't know how to read the varnishhist graph yet, but here it is :

Max 596 Scale 667 Tot: 2000



      |
      |
      |
      |
      ||
      ||
     |||
     |||
     |||
     |||
     |||
     ||| 
    ||||
    ||||
    ||||
    ||||              
   ||||||             
  |||||||||||| |  # ##################  # #      ##
+---------+---------+---------+---------+---------+---------+---------+-----
|1e-5     |1e-4     |1e-3     |1e-2     |1e-1     |1e0      |1e1      |1e2

[phk]

Varnishhist shows you the time from reception of request to ready to send answer in seconds for hits and misses.

Left hand side is 1e-5 [s] = 10 microseconds, right hand side is 1e2 [s] = 100 seconds.

The graph you show there is close to perfect.

Try setting the maximum number of threads to 230 so that varnish doesn't waste time trying to create more threads that won't fit, and then keep an eye on varnishhist to see if your responsetime suffers.

Also, consider running varnishd with '-d -d' option during testing like this, it will give you a hand CLI to query/change parameters on the fly and additional debug messages as well.

Poul-Henning

[des]

Your varnishhist(1) output shows that most hits are processed in 10 to 100 µs and misses in 1 to 100 ms, and the hitrate looks good.

If I read your varnishstat(1) output correctly, your server delivers around 4 MB of data per second, plus protocol overhead, which is quite a lot (~40-50 Mbps sustained). I would recommend switching to a 64-bit CPU (and OS) to get around the address space limitation. If that really isn't an option, you can cap the number of worker threads with -w (e.g. -w20,200) to silence the error messages.

[Thias]

After "stabilizing" some real production traffic to the varnish server, it's pushing between 100 and 160Mbps on it's public interface, and getting between 10 and 30Mbps from the backend on its private interface. Not bad... but : When I see the "Create worker thread failed 12 Cannot allocate memory" appear (I'm running "varnishlog -i Debug" to catch those), the outbound traffic drops to 30-60Mbps, and a test to a web page shows that all images are loading very slow. Those requests are unfortunately not just "a bit slow" *sigh*

I've now tried passing -w1,230,120 but although I now don't get to see the errors, things stop working properly after a while in a similar way, and "worker threads limited" and "overflowed work requests" start to increase a lot :

         230         0.00         1.54 N worker threads
         230         0.00         1.54 N worker threads created
           0         0.00         0.00 N worker threads not created
       16672       534.92       111.89 N worker threads limited
          93       -29.88         0.62 N queued work requests
       16902       534.92       113.44 N overflowed work requests
        9044         0.00        60.70 N dropped work requests

If the 32bit limitations aren't going to get worked around anytime soon, I'll definitely try to get my hands on a 64bit machine to do some more testing, although that won't be so easy...

[phk]

Thread pileups like that can be caused by slow responses from the backend. Right now we don't have a traffic-shaping facility on the backend (as in "don't hit this backend with more than 100 connections at the same time") but we probably need that down the line.

Keep an eye on the number of backend connections when these pileups happen, if the backend connections increase dramatically that's the root cause.

There really isn't any way we can work around the 32 bit issue, it's a deliberate choice we made in the design, and a significant part of the reason why Varnish is so fast as it is.

I realize that for you or anybody else, getting a 64 bit machine online will be a hazzle, but in the big scheme of things, all server cpu's you can buy today do 64bit mode, so it is mostly a transition issue.

I promise you won't be disappointed about Varnish' performance on 64 bit, it's worth it.

Poul-Henning

[Thias]

The backend server is 64bits, so I've just installed varnish there after switching the backend web daemon (lighttpd) to listen on the loopback, port 81. I'm seeing other issues now. Should I open a separate bug report? Or maybe better : Post on one of the mailing-lists?

[phk]

start another ticket for that.

Poul-Henning

[des]

I'd prefer to discuss it on the mailing list, and open a ticket if / when we identify an actual bug or shortcoming.