Mailing List Archive

On Mon, 30 Mar 2015 14:13:56 +0200 Christian Loos <cloos@netcologne.de>
wrote:
> after upgrading from 4.2.9 to 4.2.10 I noticed a drop in loading a
> ticket with REST from 3.5 to 6.0 seconds.
> At the same time, loading the same ticket with the WebUI remained stable
> at 1 second.
> This is from our (nearly unused) test system, so there are no side
> effects from many users using the WebUI or so.
>
> I couldn't find any relevant changes between 4.2.9 and 4.2.10.
>
> Maybe you have an idea what is going on here?

I'm not aware of any intentional changes in REST between 4.2.9 and
4.2.10 -- which implies that the performance drop is due to
second-order changes.

What is the content of the REST request? If you start up a
single-threaded server with Devel::NYTProf on it and make the REST
request, where does it say the time is being spent?
- Alex

Am 30.03.2015 um 19:25 schrieb Alex Vandiver:
> I'm not aware of any intentional changes in REST between 4.2.9 and
> 4.2.10 -- which implies that the performance drop is due to
> second-order changes.
>
> What is the content of the REST request? If you start up a
> single-threaded server with Devel::NYTProf on it and make the REST
> request, where does it say the time is being spent?
> - Alex

I have done this:

sudo perl -d:NYTProf /opt/rt4/sbin/rt-server --server Standalone --port 8080
wget http://localhost:8080/REST/1.0/ticket/10587/history?format=l
nytprofhtml --open

Attached the nytprofhtml output for
/opt/rt4/share/html/REST/1.0/Forms/ticket/history

As I'm not familiar with NYTProf I'm not sure if this is the correct
output you want.
If not, it would be great if you can provide details steps to profile
the REST call.

Thanks.

Chris

On Tue, 31 Mar 2015 10:58:02 +0200 Christian Loos <cloos@netcologne.de>
wrote:
> Am 30.03.2015 um 19:25 schrieb Alex Vandiver:
> > I'm not aware of any intentional changes in REST between 4.2.9 and
> > 4.2.10 -- which implies that the performance drop is due to
> > second-order changes.
> >
> > What is the content of the REST request? If you start up a
> > single-threaded server with Devel::NYTProf on it and make the REST
> > request, where does it say the time is being spent?
> > - Alex
>
> I have done this:
>
> sudo perl -d:NYTProf /opt/rt4/sbin/rt-server --server Standalone --port 8080
> wget http://localhost:8080/REST/1.0/ticket/10587/history?format=l
> nytprofhtml --open
>
> Attached the nytprofhtml output for
> /opt/rt4/share/html/REST/1.0/Forms/ticket/history
>
> As I'm not familiar with NYTProf I'm not sure if this is the correct
> output you want.
> If not, it would be great if you can provide details steps to profile
> the REST call.

You've profiled the right thing, but not looked at the correct output
from NYTProf. Namely, all this says is "7.24s were spent
in /REST/1.0/show". You'll need to drill down into there to find out
where the time is spent.

Since you're looking for a regression, I suggest you profile both
4.2.10 and 4.2.9 (using the same steps you did above) and explore both
profile outputs in parallel, looking for where the extra 2.5s is coming
from.

As a side note, 100k is pushing what should be sent to rt-devel. If
you need to share the nytprof outputs, please put the generated HTML
trees on a webserver and provide a link.
- Alex

Am 31.03.2015 um 19:54 schrieb Alex Vandiver:
> You've profiled the right thing, but not looked at the correct output
> from NYTProf. Namely, all this says is "7.24s were spent
> in /REST/1.0/show". You'll need to drill down into there to find out
> where the time is spent.
>
> Since you're looking for a regression, I suggest you profile both
> 4.2.10 and 4.2.9 (using the same steps you did above) and explore both
> profile outputs in parallel, looking for where the extra 2.5s is coming
> from.

OK, I found the bad guy: w3m ;-)

As part of our RT 4.2.10 upgrade I installed HTML::FormatExternal.
So we use w3m for HTML2Text conversions.

NYTProf shows for 4.2.9 (core formater)
# spent 141ms making 12 calls to
RT::Interface::Email::ConvertHTMLToText, avg 11.7ms/call

and for 4.2.10 (w3m formater)
# spent 10.1s making 12 calls to
RT::Interface::Email::ConvertHTMLToText, avg 840ms/call

which is called in RT::Transaction->Content.

A quick test of the other formaters just confirms what is already
mentioned in the commit [1]:
* core is the fastest (2.9s)
* elinks is the slowest (5.7s)
* the others are in between (4.6s)

So as long as you don't find an reliable Perl HTML2Text converter, I
think there isn't much we can do here.


Chris

[1] https://github.com/bestpractical/rt/commit/c40ba50