Horrifically slow AJAX -- how to debug?

[Joe Barnhart]

I have an issue, but my question is really a "meta issue" about the issue...

I'm developing a large database application which uses a postgres server which is separate from the web2py installation (on nginx).  When geting pages currently the time to fetch a page is 2-10 seconds!  I have profiled the database -- it's returning the data in about 100ms.  I profiled the controller (including the database) and it's responding in 200-400ms.  So my task is to find the extra 1.5 to 9.5 seconds.

Which leads to my question -- how to debug issues like this?  I'm familiar with postgres and the tools there to analyze and explain a query.  I can instrument my web2py code and have it tell me the resulting time to run a controller.  But the overall application, with the interaction of two computers, browsers, etc. is just too fragmented for me to see where the time is going and it's too complicated to post a simple example here and have one of you geniuses tell me the problem. 

I really need some strategies for debugging these system issues myself.  Any tips or tools I should be looking at?  (For example I have an use WingIDE which has been very helpful with some issues but not this one so much.)

Joe

[Massimo Di Pierro]

Did you try the {{=response.toolbar()}} ?

[villas]

For visualizing network latency etc,  Firebug is great (available for Firefox). 
I think all major browsers have a similar development tool.

[Anthony]

You mention ajax but then discuss time to load a whole page. Are there multiple ajax requests coming from the page? If so, does each ajax request require the session (locking of the session file will force the ajax requests to be handled serially instead of in parallel)? If not, you can do session.forget(response) early in the ajax request to unlock the session file and allow the next ajax request to start processing.

Anthony

[Joe Barnhart]

Hi Massimo --

Yes, I added the response.toolbar() to my ajax response and placed it at the bottom of the served page.  It basically confirmed the Postgres tools -- my page is served in around 30ms for a typical request (actually faster than "explain analyze" predicted).  But the wall clock says it takes between 2-10 seconds to serve the page.  Maybe web2py is so fast I'm experiencing time dilation. ;-)

My guess is that the slowness comes from the interplay of the pieces in my total setup.  So far I have:

1.  A 6-core AMD processor running Linux

2.  Postgres running on top of it

3.  Virtualbox running, with 3 guests.

4.  Web2py and nginx in a virtualbox guest, on Linux

5.  "Host-only" networking for speedy web2py-postgress communications between VB host and guest

6.  "Bridged" networking for external communication to web2py instance

So far the loading is one user, so I know I'm not getting too many requests.  The networking setup works very well since i use the same channels for development on the web2py virtualbox -- host-only when at my Linux box and bridged when at a different computer.  Response is snappy and immediate in all cases.  Only the web2py-nginx-postgres path seems to be excessively slow, and only when I'm using jQuery AJAX requests.

[Joe Barnhart]

Hi villas --

Yes, I've used both Firefox and Chrome to try and understand what's going on.  Both tools show the actual time for the AJAX response -- seconds insted of milliseconds.  But they can't give me any detail of what's going on during the request.  They only show the time waiting for the AJAX response.  Hence my quandry.

-- Joe

[Joe Barnhart]

I basically have tried two AJAX requests and one request.  Both have resulted in the same outcome.  I also tried the session._unlock(response) suggestion but without any measurable result.

Clearly something in my setup is snarled but finding it is proving difficult.

-- Joe

[Derek]

Use the 'network'  tab on chrome... button... right click, save as HAR, attach it here.

[Joe Barnhart]

Here you go.  It shows the long time in the ajax request, but I can't see why.

-- Joe

[Joe Barnhart]

Here is something odd.  I was looking through the logs of nginx and uwsgi to see if there are any smoking guns there.  In the uwsgi log file I can at least see the log contains the same time I experience in "real time" when I select the page:

[pid: 2767|app: 0|req: 700/1896] 67.161.165.180 () {50 vars in 1007 bytes} [Tue Jul  2 23:45:17 2013] GET /swim_smarter/results/meetevents/?meet=4232&event=22F&pf=f => generated 6353 bytes in 3132 msecs (HTTP/1.1 200) 5 headers in 218 bytes (1 switches on core 0)

So uwsgi sees the same time delay I see.  I don't know if this is due to uwsgi or which other component.  I'm not very familiar with nginx and uwsgi and may have misconfigured it when setting it up.  It may be that a different web server would be a better fit for my goals.

Eventually this will be a very heavily used database application with many gigabytes of data, but it may take a year or two to build up to its full potential.  I could start with something simpler to configure and upgrade it as the volume builds.

Joe

[Massimo Di Pierro]

Ajax aside, you should be able to start web2py locally and call

http://127.0.0.1:8000/swim_smarter/results/meetevents/?meet=4232&event=22F&pf=f

If you see the slow down you can eliminate problems with uwsgi and nginx

[Joe Barnhart]

Yes, you're right.  The site overall feels much quicker when talking to it directly, bypassing nginx and uwsgi.  The query below takes in the 0.5-1 second range -- still somewhat slower than expected, but much quicker than thru port 80.  This does indicate some shenanigans going on in my server stack.

I'll do something about nginx and then see if the problem persists.

-- Joe B. 

[Derek]

You're returning 72 rows, which equates to a 10k file, it's gzipped, so there's latency on the server side which has to gzip it. If you can get it under 5k the server may decide not to gzip it, thus speeding it up. Also, you are returning invalid attributes in your td tags. If you want to have custom data in your classes, you must prefix it with the 'data-'. See here for more info...

http://www.javascriptkit.com/dhtmltutors/customattributes.shtml

So what I'm seeing in the HAR is that it takes you 4 seconds to get data that is 10k...

Also, I am not sure if you changed it, but 11.11.11.111 is an ip address on the internet... it belongs to DoD Network Information Center. You probably don't want to use 11.anything for your internal ip addresses. You'll have routing issues! Use the appropriate private ip address segments, please!

https://en.wikipedia.org/wiki/Private_network

[Derek]

Forgot to add, if your nginx is setup to do reverse ip lookups, you could speed that up by adding an entry in the hosts file of the servers.

[Joe Barnhart]

Hi Derek --

That's great information.  I didn't know about the "data-" part of custom tags -- I thought any tags were legal as long as I didn't use "id" or "class" or something else reserved.  But I'm a newcomer to HTML 5 and I want to be as compliant as possible.  That 10K number sounds too large for this AJAX response.  I'll have to look at it with my browser again to make sure I'm not sending too much stuff.

I did overwrite the address since it was showing the actual external IP address of the site and I'm not ready for visitors yet.  So I am actually using a routable address for the site itself.  (I invested in a local ISP so I have learned more about routing than I ever wanted to know!)

-- Joe

On Wednesday, July 3, 2013 1:17:32 PM UTC-7, Derek wrote: