REST performance drop after upgrade from 4.2.9 to 4.2.10

Hi,

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?

Chris

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

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

nytprof.pdf (73.2 KB)

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

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 :wink:

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