Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
hoytech opened this issue Jan 11, 2016 · 5 comments

Comments

@hoytech
Copy link

hoytech commented Jan 11, 2016

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
Copy link
Author

hoytech commented Jan 11, 2016

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

@bodo-hugo-barwich
Copy link

bodo-hugo-barwich commented Jul 24, 2021

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
Copy link

bodo-hugo-barwich commented Jul 24, 2021

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

  • the Chunk Size is far too small for big work loads
  • and waiting for the Write Queue to get empty is not the best strategy to handle big work loads and achieve best performance

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
Copy link

bodo-hugo-barwich commented Sep 4, 2021

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
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants