search

miyagawa / Twiggy

AnyEvent based non-blocking PSGI web server (like Thin)
http://search.cpan.org/dist/Twiggy
Other
104 stars 34 forks source link

Spurious(?) "Deep recursion" message from Twiggy::Server+Plack::Middleware::Static #49

Open hoytech opened 8 years ago

hoytech commented 8 years ago

Apologies if this is a known issue. This is on Ubuntu Linux 15.04:

$ cpanm Twiggy Plack --sudo 
Twiggy is up to date. (0.1025)
Plack is up to date. (1.0039)

Create a "big" file:

$ perl -E 'print "a" x 1_000_000' > file.txt

Start Twiggy::Server with Plack::Middleware::Static:

$ perl -MPlack::Middleware::Static -MTwiggy::Server -E 'Twiggy::Server->new(port => 9876)->register_service(Plack::Middleware::Static->wrap(undef, root => ".", path => "/")); AE::cv->recv'

In a new terminal, hit the server with curl:

$ curl -s localhost:9876/file.txt|wc -c
1000000

In original terminal there is this warning:

Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/local/share/perl/5.20.2/Twiggy/Server.pm line 529, <$fh> chunk 100.

I say "spurious" in the title because the file seems to have downloaded OK according to wc above... I guess the deep recursion isn't actually a problem somehow?

Thanks!

hoytech commented 8 years ago

Nevermind, I actually read #1 and this issue is not related to AIO as far as I know :)

bodo-hugo-barwich commented 3 years ago

I'm observing this issue still with the latest version of Twiggy in my web project Plack Twiggy PWA when loading big images:

127.0.0.1 - - [24/Jul/2021:14:35:50 +0000] "GET /images/coffee8.jpg HTTP/1.1" 200 499668 "https://plack-twiggy-pwa.glitch.me/service-worker" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"

Deep recursion on subroutine "AnyEvent::Handle::push_write" at /app/perl5/lib/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.

127.0.0.1 - - [24/Jul/2021:14:35:50 +0000] "GET /images/coffee9.jpg HTTP/1.1" 200 871951 "https://plack-twiggy-pwa.glitch.me/service-worker" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"

Deep recursion on subroutine "AnyEvent::Handle::push_write" at /app/perl5/lib/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.

127.0.0.1 - - [24/Jul/2021:14:35:50 +0000] "GET /images/coffee4.jpg HTTP/1.1" 200 666732 "https://plack-twiggy-pwa.glitch.me/service-worker" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"

Deep recursion on subroutine "AnyEvent::Handle::push_write" at /app/perl5/lib/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.

The System where the Web Server runs on is a ubuntu:xenial Container. ... a very common Setup for Serverless Infrastructure ...

Installed Versions:

Checking if you have AnyEvent 0 ... Yes (7.17)
Checking if you have Twiggy 0 ... Yes (0.1026)
Checking if you have Plack 0 ... Yes (1.0048)
bodo-hugo-barwich commented 3 years ago

Seeing the Warning in the context of the Server Logic at Twiggy::Server::on_drain Event I understand that the Server Logic waits for the Write Queue to get empty in order to write the next Chunk of Data. With Twiggy::Server::read_chunk_size == 4096 as seen at Twiggy::Server::new Constructor I think that

When writing high performant applications that handle big workloads I found that reducing read and write events with defining bigger chunk sizes produces the best performance. And would not filling up the Write Queue to its Memory Limit enable the Server to best distribute the workload according to the bandwidth rather then waiting for the queue to get empty?

bodo-hugo-barwich commented 3 years ago

As seen in the synopsis of the Twiggy documentation I intended to override the default values with more generous ones: Twiggy Server Synopsis

#----------------------------------------------------------------------------
#URL Mapping

my $web = builder {
  #Graphic Elements Mapping
  enable "Static", path => qr#^/(images|css|js|html)#, root => $webroot;
  #Configure Logging
  enable "Plack::Middleware::AccessLog::Timed"
    , format => '%{X-FORWARDED-PROTO}i:%V (%h,%{X-FORWARDED-FOR}i) %{%F:%T}t [%D] '
      . '"Mime:%{Content-Type}o" "%r" %>s %b "%{Referer}i" "%{User-agent}i"';
  #Any other Content
  $app;
};

#----------------------------------------------------------------------------
#Create Service Instance

print "args dmp:\n", dump @ARGV ;
print "\n";

print "ENV dmp:\n", dump %ENV ;
print "\n";

my $host = '0.0.0.0';
my $port = $ENV{'PORT'} || 3000;

my $server = Twiggy::Server->new(
    host => $host,
    port => $port,
    read_chunk_size => 32768,
);

#Start Service
$server->run($web);

This does work in the sense that the server is executable and responsive.

pwa_web | ENV dmp:
pwa_web | (
pwa_web |   "PERL_MM_OPT",
pwa_web |   "INSTALL_BASE=/home/plack-pwa/perl5",
pwa_web |   "PWD",
pwa_web |   "/home/plack-pwa",
pwa_web |   "PERL5LIB",
pwa_web |   "/home/plack-pwa/perl5/lib/perl5",
pwa_web |   "PATH",
pwa_web |   "/home/plack-pwa/perl5/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin",
pwa_web |   "COMPONENT",
pwa_web |   "pwa_web",
pwa_web |   "HOSTNAME",
pwa_web |   "7001e1d01f1a",
pwa_web |   "PERL_MB_OPT",
pwa_web |   "--install_base \"/home/plack-pwa/perl5\"",
pwa_web |   "HOME",
pwa_web |   "/home/plack-pwa",
pwa_web |   "PERL_LOCAL_LIB_ROOT",
pwa_web |   "/home/plack-pwa/perl5",
pwa_web |   "PLACK_ENV",
pwa_web |   "development",
pwa_web | )
pwa_web | -:localhost:3000 (172.18.0.1,-) [2021-09-04:13:00:02] [125056] "Mime:text/html" "GET / HTTP/1.1" 200 3693 "-" "Mozilla/5.0 (Unknown; Linux x86_64) AppleWebKit/538.1 (KHTML, like Gecko) PhantomJS/2.1.1 Safari/538.1"
pwa_web | -:localhost:3000 (172.18.0.1,-) [2021-09-04:15:34:18] [64384] "Mime:text/html" "GET / HTTP/1.1" 200 3693 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"
pwa_web | -:localhost:3000 (172.18.0.1,-) [2021-09-04:15:34:18] [67243] "Mime:application/javascript" "GET /service-worker HTTP/1.1" 200 2956 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"
pwa_web | -:localhost:3000 (172.18.0.1,-) [2021-09-04:15:34:19] [8240] "Mime:text/html" "GET / HTTP/1.1" 200 3693 "http://localhost:3000/service-worker" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"
pwa_web | -:localhost:3000 (172.18.0.1,-) [2021-09-04:15:34:19] [11162] "Mime:text/html" "GET /index.html HTTP/1.1" 200 3693 "http://localhost:3000/service-worker" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"
pwa_web | -:localhost:3000 (172.18.0.1,-) [2021-09-04:15:35:14] [10681] "Mime:text/html" "GET / HTTP/1.1" 200 3693 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Firefox/78.0"

But now it does not log anymore the static resource requests. The Browser Console documents that the images were requested but in the Server Log there doesn't appear any Log Entry about it:

Cache URL 'http://localhost:3000/images/coffee1.jpg': fetching ... service-worker:53:11
Cache URL 'http://localhost:3000/images/coffee4.jpg': fetching ... service-worker:53:11
Cache URL 'http://localhost:3000/images/coffee3.jpg': fetching ... service-worker:53:11
Cache URL 'http://localhost:3000/images/coffee2.jpg': fetching ... service-worker:53:11
Cache URL 'http://localhost:3000/images/coffee9.jpg': fetching ... service-worker:53:11
Cache URL 'http://localhost:3000/images/coffee5.jpg': fetching ... service-worker:53:11
Cache URL 'http://localhost:3000/images/coffee6.jpg': fetching ... service-worker:53:11
Cache URL 'http://localhost:3000/images/coffee8.jpg': fetching ... service-worker:53:11
Cache URL 'http://localhost:3000/images/coffee7.jpg': fetching ... service-worker:53:11

Now when setting the value read_chunk_size in the constructor back to 4096 the errors show up again but their Log Entries don't show.

-:localhost:3000 (127.0.0.1,-) [2021-09-04:19:40:41] [429179] "Mime:text/html" "GET / HTTP/1.1" 200 3693 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36"
-:localhost:3000 (127.0.0.1,-) [2021-09-04:19:40:42] [69855] "Mime:application/javascript" "GET /service-worker HTTP/1.1" 200 2956 "http://localhost:3000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36"
-:localhost:3000 (127.0.0.1,-) [2021-09-04:19:40:42] [19441] "Mime:text/html" "GET / HTTP/1.1" 200 3693 "http://localhost:3000/service-worker" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36"
-:localhost:3000 (127.0.0.1,-) [2021-09-04:19:40:42] [23941] "Mime:text/html" "GET /index.html HTTP/1.1" 200 3693 "http://localhost:3000/service-worker" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36"
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.
Deep recursion on subroutine "AnyEvent::Handle::push_write" at /usr/share/perl5/Twiggy/Server.pm line 529, <$fh> chunk 100.

So, the Error does not happen anymore and also the site rendering is speeded up very much which does confirm the earlier conclusion but the Server Logs are incomplete now which makes the solution not so nice.

bodo-hugo-barwich commented 3 years ago

According to the Error Message and the relationship with the read_chunk_size setting the upper limit before the error occurs can be calculated as 400 KB per resource:

$ echo "scale=3; (4096*100)/1024"|bc -l
400.000