Incorporate Server Timing API

[westonruter]

To help facilitate debugging issues related to the performance of the preprocessor, we should leverage the new Server Timing API to report how long each sanitizer is taking to run, how long WordPress took to generate the page prior to the sanitizers running, etc.

Relates to #959.

[igkuz]

@westonruter hi! Is it possible to turn off Server Timing headers in response? For example, with default configs for PHP-FPM + Nginx as a reverse proxy, Nginx drops requests as headers are too big. Tunning the fastcgi buffers fixes the problem, but it would be great to make these headers optional.
I didn't find in code, how to turn off them...

[westonruter]

@igkuz It's not currently possible to turn off the Server-Timing headers in the response. What are the Server-Timing headers you are seeing? How are they too big? I see just:

Server-Timing: amp_output_buffer;desc="AMP Output Buffer";dur=325.990915
Server-Timing: amp_dom_parse;desc="AMP DOM Parse";dur=4.322052
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.546932
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=6.416798
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.148058
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.276089
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.092030
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.113010
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.106812
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.201941
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.336885
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.022888
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.175953
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.034809
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=0.024796
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=38.730860
Server-Timing: amp_sanitize;desc="AMP_Tag_And_Attribute_Sanitizer";dur=81.669092
Server-Timing: amp_dom_serialize;desc="AMP DOM Serialize";dur=7.952929

Note that this is only for a response when the post-processor is invoked because the processed result is not cached yet. Once the post-processed response is cached, then the sanitizers are bypassed and none of the Server-Timing headers are sent.

[westonruter]

(As I paste that, I see something is wrong in that it is repeating AMP_Tag_And_Attribute_Sanitizer when it should be noting each separate sanitizer that is running. I'll fix this separately.)

[igkuz]

@westonruter I see the same and AMP_Tag_And_Attribute_Sanitizer is repeating for several times. And when the page is big enough it's a problem. We're using the latest beta build, you can check the output here http://goo.gl/jTqZCW.

[westonruter]

@igkuz The issue of duplicated sanitizer names in the headers will be fixed with #1283.

How many sanitizers are you using? While I expect there to be numerous instances of the Server-Timing header, each instance is relatively short considering how long cookie headers can be. I'm confused as to why Nginx is complaining. I've seen Nginx break when an individual header is too long, but not when there are numerous individual headers. Is there a default limit on the byte size of all response headers combined?

[igkuz]

@westonruter
from Nginx docs:
fastcgi_buffer_size:
By default, the buffer size is equal to one memory page. This is either 4K or 8K, depending on a platform. It can be made smaller, however.

So if you place for example fastcgi_buffer_size 32k; everything is ok. PHP-FPM settings are not far from default ubuntu apt repo package, the changes are not connected with buffers.

We added 4 Sanitizers to the array in our plugin.

[westonruter]

@igkuz I'm seeing a very large number of Server-Timing headers on your URL—60 in fact.

$ curl -i https://setka.io/blog/how-to-use-font-pairs/?amp | grep 'Server-Timing:' | wc -l
60

This is not expected. There should only be ~22 such headers since you added 4 sanitizers.

[igkuz]

@westonruter you're correct, it's 60 of them, we're checking our code also, but still having an opportunity to turn them off would be great.

[westonruter]

@igkuz if you update the plugin to the state after #1283 is merged then you will be able to see the sanitizer names again.