[OPEN-ILS-DEV] [GSOC] System Log

[Dan Scott]

Hi Swenyu:

On Tue, Jul 03, 2012 at 10:04:15PM +0800, sy duan wrote:
> Hi everyone,
> 
>          I’m Swenyu, this year’s GSOC student. I’m optimizing the system
> performance in search. I have studied the log of OpenSRF in the file
> osrfsys.log. Which shows in a single search operation, DB calls takes as
> much time as the message processing in Tranport.pm. And the accumulated
> message processing time even surpass the DB search time. So I want to

Can you share a little more information - for example, what sort of
hardware and operating system configuration, how much data is loaded in
the database, what query you're running, etc? If we want to reproduce
your tests in the future, to ensure that we don't introduce performance
regressions, we'll need some more complete descriptions and
instructions.

> optimize the message processing method in Tranport.pm as well as the DB’s
> stored procedures. But the conclusion is drawn from my own virtual machine
> logs which has little test data in database. In most time the search only
> return 0 result. So I turned to your help. Could anyone send me a snippet

Which data set are you using currently? If it's just the 100 records
from concerto.sql, we could look at using something like the Open
Content Alliance records at http://books.scholarsportal.info/marc.html
as the basis for a high-volume test data set (like concerto.sql, we
would want to create call numbers and copies, including deleted
records/call numbers/copies and monographic parts and the like - just
with 270,000 records instead of 100!)

> of your running system log which contains some query with a large result
> set. The system log is located in /openils/var/log in your running system.

I've attached the activity.log entries pertaining to a search on our
production database, but I suspect you're looking for more than just the
standard split-up-for-syslog log entries. Maybe you could post what
particular parts of the log entries you want, as an example, and we
could pull the pertinent pieces together?

> Or could anyone point a place for me to find some real data to fill in my
> database. That will be a great help to support the optimization.

As noted, I think the Open Content Alliance MARC records would serve as
a reasonable starting point for a huge set of of MARC, if that's the
kind of data you're looking for. (I'm not sure if you want patron data
and org unit data and transaction histories and everything else, too,
but as you're focused on search I'm guessing MARC + call numbers +
copies is your primary interest for now.)
-------------- next part --------------
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3038:./osrf_json_gateway.c:302:134184874830388] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.multiclass.query {"org_unit":105,"depth":1,"limit":10,"offset":0,"visibility_limit":3000,"default_class":"keyword"}, "apache", 1
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3038:./osrf_json_gateway.c:302:134184874830389] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 889694
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3852:./osrf_json_gateway.c:302:134184878538522] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 889695
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3044:./osrf_json_gateway.c:302:134184874930443] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 889636
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3826:./osrf_json_gateway.c:302:1341848778382612] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 354247
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:2986:./osrf_json_gateway.c:302:134184871729868] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 885982
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3035:./osrf_json_gateway.c:302:134184874730353] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 885968
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3038:./osrf_json_gateway.c:302:1341848748303810] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 293264
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3826:./osrf_json_gateway.c:302:1341848778382613] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 832165
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:2986:./osrf_json_gateway.c:302:134184871729869] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 38167
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3852:./osrf_json_gateway.c:302:134184878538523] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.mods_slim.retrieve 355300
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3038:./osrf_json_gateway.c:302:1341848748303811] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 889694, ""
2012-07-09 11:46:44 protostar osrf_json_gw: [ACT:3035:./osrf_json_gateway.c:302:134184874730354] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 354247, ""
2012-07-09 11:46:45 protostar osrf_json_gw: [ACT:3852:./osrf_json_gateway.c:302:134184878538524] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 885982, ""
2012-07-09 11:46:45 protostar osrf_json_gw: [ACT:3038:./osrf_json_gateway.c:302:1341848748303812] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 889695, ""
2012-07-09 11:46:45 protostar osrf_json_gw: [ACT:3035:./osrf_json_gateway.c:302:134184874730355] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 293264, ""
2012-07-09 11:46:45 protostar osrf_json_gw: [ACT:3038:./osrf_json_gateway.c:302:1341848748303813] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 885968, ""
2012-07-09 11:46:45 protostar osrf_json_gw: [ACT:2986:./osrf_json_gateway.c:302:1341848717298610] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 832165, ""
2012-07-09 11:46:45 protostar osrf_json_gw: [ACT:3038:./osrf_json_gateway.c:302:1341848748303814] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 889636, ""
2012-07-09 11:46:45 protostar osrf_json_gw: [ACT:2986:./osrf_json_gateway.c:302:1341848717298611] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 355300, ""
2012-07-09 11:46:45 protostar osrf_json_gw: [ACT:3038:./osrf_json_gateway.c:302:1341848748303815] [142.51.8.34] [] [en-CA] open-ils.search open-ils.search.biblio.record.copy_count 105, 38167, ""
2012-07-09 11:46:45 protostar osrf_http_translator: [ACT:2986:./osrf_http_translator.c:293:1341848717298612] [142.51.8.34] [] open-ils.search open-ils.search.facet_cache.retrieve "open-ils.search_9ac841389733d019221029b737c323aa_facets", 100