[OPEN-ILS-DEV] Circ History Sorting

Fri Aug 19 09:29:05 EDT 2016

Jason, thanks for the suggestions.  I checked the max_stanza_size  value and it matches the opensrf install docs recommendation of 2,000,000.  I'll try doubling that and see if it makes any difference.

No change, I still see the same log messages and the same symptoms.

I tried it with 50 items in the history, and the sort does work. 416426 Bytes.  It looks like it takes 5 seconds for the "Returned 50 result(s)" message.  So 260 results might take 26 seconds?

open-ils.cstore 2016-08-19 08:12:47 [INFO:18721:osrf_application.c:1059:14716108371914417] CALL: open-ils.cstore open-ils.cstore.direct.action.user_circ_history.search.atomic {"usr":136306},{"order_by":{"auch":"xact_start DESC"},"flesh":3,"flesh_fields":{"acn":["record"],"auch":["target_copy"],"acp":["call_number"]}},{"substream":1}

open-ils.cstore 2016-08-19 08:12:47 [INFO:18721:osrf_app_session.c:1017:14716108371914417] [open-ils.cstore] sent 416426 bytes of data to opensrf at private.localhost/client_at_virt-egdev1.larl.org_19144

open-ils.cstore 2016-08-19 08:12:47 [INFO:18721:osrf_stack.c:163:14716108371914417] Message processing duration 0.390298

[2016-08-19 08:12:52] /usr/sbin/apache2 [INFO:19144:CStoreEditor.pm:139:14716108371914417] editor[1|136306] open-ils.cstore.direct.action.user_circ_history.search.atomic: returned 50 result(s)

[2016-08-19 08:12:52] /usr/sbin/apache2 [INFO:19144:CStoreEditor.pm:139:14716108371914417] editor[1|136306] rolling back db session

[2016-08-19 08:12:52] /usr/sbin/apache2 [INFO:19144:CStoreEditor.pm:139:14716108371914417] editor[1|136306] request en-US open-ils.cstore.transaction.rollback []

Josh Stompro - LARL IT Director

-----Original Message-----
From: Open-ils-dev [mailto:open-ils-dev-bounces at list.georgialibraries.org] On Behalf Of Jason Stephenson
Sent: Thursday, August 18, 2016 6:12 PM
To: Evergreen Development Discussion List
Subject: Re: [OPEN-ILS-DEV] Circ History Sorting

Josh,

The timeout bit has to do with the client of the cstore making a "connected" session and no request coming in. After 6 seconds, the drone will close the stateful session so it can be used by another client.
This happens when something breaks the communication between client and drone, or if the client code forgets to disconnect after connecting.
(I've fixed a bug or two related to this in the past.)

If you look at the line above that, the cstore drone sent 1,582,282 bytes of data to the client. At least, it tried to do that.

You should check the max_stanza_size in your ejabberd config. It is probably set at 1,000,000 and that response was, therefore, too big.

This would explain beam and apache hitting 100% CPU for a while.

So, my guess is the cstore response was too large given a typical ejabberd config. Ejabberd threw the response out and the client never found out, so it sat waiting on a response that was not coming. After 6 seconds, the drone closed the session opened by the client.

You can try increasing the max_stanza_size in your ejabberd configuration.

HtH,
Jason

On 08/18/2016 04:21 PM, Josh Stompro wrote:
> Hello, I'm having trouble with sorting the columns in the my opac, 
> circ history screen.  I've have a 2.10.5 test system setup with all 
> our production data on a single VM.  Maybe the VM just doesn't have 
> enough resources.
> 
>  
> 
> I have 226 items in my history when I look at action.usr_circ_history.
> 
>  
> 
> Viewing and paging through the history works fine.  It looks like when 
> doing normal viewing and paging the  cstore query is used directly, 
> and it is limited to 15 items per page.
> 
>  
> 
> When I click the title column to sort I see the following.  The web 
> page takes about 30 seconds to re-load and says that I have no data in 
> my history.  When looking at atop I see beam.smp go to 100% CPU for 60 
> seconds, and then and apache process at 100% CPU for 45 seconds.
> 
>  
> 
> When I look at the logs I see the following.  It looks like cstore 
> waits
> 6 seconds for a response and then gives up... but the system must still 
> be pulling in the data and then processing it, even though cstore gave up.
> 
> [2016-08-17 15:52:25] /usr/sbin/apache2 
> [INFO:8529:CStoreEditor.pm:139:1471433103852926] editor[1|127625] 
> request en-US 
> open-ils.cstore.direct.action.user_circ_history.search.atomic
> [{"usr":127625},{"flesh_fields":{"auch":["target_copy"],"acp":["call_n
> umber"],"acn":["record"]},"order_by":{"auch":"xact_start
> DESC"},"flesh":3},{"substream":1}]
> 
> open-ils.cstore 2016-08-17 15:52:25
> [INFO:23530:osrf_application.c:1059:1471433103852927] CALL:
> open-ils.cstore
> open-ils.cstore.direct.action.user_circ_history.search.atomic
> {"usr":127625},{"order_by":{"auch":"xact_start
> DESC"},"flesh":3,"flesh_fields":{"auch":["target_copy"],"acp":["call_n
> umber"],"acn":["record"]}},{"substream":1}
> 
> open-ils.cstore 2016-08-17 15:52:26
> [INFO:23530:osrf_app_session.c:1017:1471433103852927] 
> [open-ils.cstore] sent 1582282 bytes of data to
> opensrf at private.localhost/client_at_virt-egdev1.larl.org_8529
> 
> open-ils.cstore 2016-08-17 15:52:26
> [INFO:23530:osrf_stack.c:163:1471433103852927] Message processing 
> duration 0.761759
> 
> open-ils.cstore 2016-08-17 15:52:32
> [INFO:23530:osrf_prefork.c:496:1471433103852927] No request was 
> received in 6 seconds, exiting stateful session
> 
> open-ils.cstore 2016-08-17 15:52:32
> [INFO:23530:osrf_app_session.c:1017:1471433103852927] 
> [open-ils.cstore] sent 196 bytes of data to
> opensrf at private.localhost/client_at_virt-egdev1.larl.org_8529
> 
> [2016-08-17 15:53:25] /usr/sbin/apache2 
> [INFO:8529:CStoreEditor.pm:139:1471433103852927] editor[1|127625] 
> request returned no data :
> open-ils.cstore.direct.action.user_circ_history.search.atomic
> 
> [2016-08-17 15:53:25] /usr/sbin/apache2 
> [INFO:8529:CStoreEditor.pm:139:1471433103852927] editor[1|127625] 
> rolling back db session
> 
> [2016-08-17 15:53:25] /usr/sbin/apache2 
> [INFO:8529:CStoreEditor.pm:139:1471433103852927] editor[1|127625] 
> request en-US open-ils.cstore.transaction.rollback []
> 
>  
> 
> I was looking where the 6 second cstore timeout was set, and all I see 
> in opensrf.xml is the <keepalive> set to 6, is that the timeout?
> 
>  
> 
> From looking at the code for this feature,
> 
> http://git.evergreen-ils.org/?p=Evergreen.git;a=commitdiff;h=c8493cabf
> 211ebfd14bfd179923f8bc6622334d9;hp=f1e09f95eb069494e93da74111c91a5788e
> e369d
> 
>  
> 
> It looks like when sorting is enabled, the full list of history items 
> is pulled and the TT code in circ_history.tt2 does the sorting and paging.
> So on each page load the entire list of history items needs to be 
> pulled and processed.  So it goes from having to deal with 15 items 
> max, to
> 250-5000 items.  I just checked our history table and see that the 
> most history someone has is 5000 items.  Is there any chance that this 
> code can deal with 5000 items in a reasonable time period?  It looks 
> like it is fleshing the record, so including the full marcxml data for 
> each of those 5000 items, mainly to pull out the title non filing 
> info, that gets to be a big chunk of data to move around for each page load.
> 
>  
> 
> As it is, If I go through and click on each of the sort options while 
> I'm waiting for the page to load, which I can see an impatient patron 
> doing to try to elicit a response from the page, I start a new request 
> for each click.  This causes my test vm to become unresponsive to all 
> other catalog requests, with beam.smp sitting at 300% Cpu usage, so an 
> easy way for a user to DOS the system intentionally or unintentionally.
> 
>  
> 
> What would be a good strategy for handling this more efficiently?  
> Push everything to the database with a custom query that generates the 
> title sort field and negates the need to do processing in circ_history.tt2?
> Are there any materialized views that generate a title_sort field 
> already?  Could this data be cached in memcached?
> 
>  
> 
> I can see that if I'm really trying to look at my history, I might 
> make a bunch of requests in a short time period, various sorts, and 
> paging through the results, so making this more efficient would help.
> 
>  
> 
> Josh
> 
>  
> 
>  
> 
> Lake Agassiz Regional Library - Moorhead MN larl.org
> 
> Josh Stompro     | Office 218.233.3757 EXT-139
> 
> LARL IT Director | Cell 218.790.2110
> 
>  
> 