This repository has been archived by the owner on May 28, 2024. It is now read-only.
-
Notifications
You must be signed in to change notification settings - Fork 2
Analysis
Darren Hardy edited this page Nov 21, 2016
·
11 revisions
The summary is that:
- We're spending most of our time in the
to_solrmethod running application logic - We're making a lot of requests to Fedora which causes about a third of the time to be idle
- Our throughput, which is dependent on the average response time and the concurrency configured, was last measured at ~200 rpm.
See this issue for details.
We're primarily using New Relic for performance analysis.
New Relic offers a dashboard with many metrics:
- Request time metrics over time (ms-per-request)
- Throughput metrics over time (requests-per-min)
- Network-level summary metrics for external services called within a request (e.g., HTTP traffic)
- A performance index metric over time (Apdex score)
- Error rates
- Method-level metrics
- Isolating specific slow transactions and seeing code traces
- Creating events for custom metrics
- Ruby VM memory usage
We also have some metrics from our own logging:
- Time spent in
Dor.load_instance(ms) - Time spent in
.to_solr(ms)
We also have system-level metrics for memory, swap, and CPU usage. Our production machines are 16x16GB.
This page consists of various notes we've collected from various cursory performance analyses.
See the performance analysis ticket
We'd like to be able to reindex all objects in 3 days. That's about 275 requests-per-minute sustained, assuming 1.2M objects (which is what we have in production today). A single collection shouldn't take longer than a day.
We have New Relic performance metrics enabled in stage and production. Visit the dashboard analytics. Briefly, it shows heavy traffic between dor-indexing-app and Fedora, and that the average reindex request takes about 9 seconds. Our New Relic subscription level limits our analytics to traffic within the last day.
For a random hour during the 11/1 afternoon, dor-indexing-app processed 1,782 reindexing requests for 370 distinct objects. Here's the top items it processed in terms of possible duplicates (times reindexed + druid):
40 zb517bz8641
40 kc397mg3263
40 jy979mg9266
38 vc197fb5252
38 jf519vq4315
37 wq896fg8130
37 mp901fy8921
37 df769cg5221
36 px101cw4044
36 nb762gg9557
36 jy372gr6295
36 gj345wc9551
35 wv318qh5607
35 ty511cf0931
35 rm918rr7513
35 dy463mm0466
35 bj405rb0597
4 zv569jd5812
4 zs646rk3069
4 zp751sr6861
4 zm810wk7845
4 zd114bn3119
4 yz752wq7127
4 yz372yd3728
4 yz335ww8221
The source of these requests is ActiveMQ, a java message broker. Here's an example request:
"GET /dor/reindex/druid:ht613wb4564?commitWithin=10000 HTTP/1.1" 200 48 "-" "Apache-HttpClient/4.3.6 (java 1.5)"
This is a random DOR item in production using a common-accessioning console -- it takes a total of ~13 seconds to do (a) and (b) together, and it reads all or part of 9 objects from Fedora, as well as information from the workflow service, for indexing the druid:bb021tj7970 object:
| Object | Type | Title |
|---|---|---|
| druid:bb021tj7970 | Item | A New Map of Pennsylvania. (inset) Profile of the Pennsylvania Canal. -- Pennsylvania.: H.S. Tanner, Philadelphia, 1836 |
| druid:bb163sd6279 | Workflow | DOR sdrIngestWF |
| druid:nb274zx7788 | Workflow | DOR disseminationWF |
| druid:rs056hz6024 | Workflow | assemblyWF |
| druid:sq161jk2248 | AdminPolicy | David Rumsey Map Collection |
| druid:tm388wy6148 | Workflow | DOR accessionWF |
| druid:xh235dd9059 | Collection | David Rumsey Map Collection at Stanford University Libraries |
| druid:yp220bx1022 | Workflow | versioningWF |
| druid:yt984hn7118 | Workflow | disseminationWF |
The following log output shows the actions taken during the (a) read object and (b) convert to Solr document phases. The times are (a) real 1.38s and utime 0.86, and (b) real 11.55s utime 6.68.
[7] pry(main)> item = nil; Benchmark.measure { item = Dor.load_instance('druid:bb021tj7970') }
D, [2016-11-01T12:47:47.071218 #29163] DEBUG -- : Loaded datastream list for druid:bb021tj7970 (57.0ms)
D, [2016-11-01T12:47:47.145300 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/RELS-EXT (71.8ms)
D, [2016-11-01T12:47:47.221184 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/RELS-EXT (74.3ms)
D, [2016-11-01T12:47:47.309658 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/identityMetadata (85.1ms)
D, [2016-11-01T12:47:47.390342 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/identityMetadata (79.9ms)
D, [2016-11-01T12:47:47.468245 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/workflows (74.7ms)
D, [2016-11-01T12:47:47.552127 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/contentMetadata (82.2ms)
D, [2016-11-01T12:47:47.645299 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/rightsMetadata (86.5ms)
D, [2016-11-01T12:47:47.709730 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/rightsMetadata (62.6ms)
D, [2016-11-01T12:47:47.775848 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/descMetadata (63.6ms)
D, [2016-11-01T12:47:47.848395 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/provenanceMetadata (70.0ms)
D, [2016-11-01T12:47:47.921377 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/provenanceMetadata (70.3ms)
D, [2016-11-01T12:47:48.003416 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/technicalMetadata (80.0ms)
D, [2016-11-01T12:47:48.085960 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/versionMetadata (80.8ms)
D, [2016-11-01T12:47:48.171076 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/versionMetadata (83.5ms)
D, [2016-11-01T12:47:48.256985 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/versionMetadata (81.4ms)
D, [2016-11-01T12:47:48.337356 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/workflows (78.6ms)
=> #<Benchmark::Tms:0x00000002bf7820
@cstime=0.0,
@cutime=0.0,
@label="",
@real=1.3803172879997874,
@stime=0.06000000000000005,
@total=0.9200000000000004,
@utime=0.8600000000000003>
[8] pry(main)> Benchmark.measure { solr_doc = item.to_solr }
D, [2016-11-01T12:47:52.955536 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/DC (70.9ms)
D, [2016-11-01T12:47:53.011952 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/events (55.1ms)
D, [2016-11-01T12:47:53.176699 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/contentMetadata (52.3ms)
D, [2016-11-01T12:47:53.239839 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/rightsMetadata (59.8ms)
D, [2016-11-01T12:47:53.305258 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/descMetadata (64.2ms)
D, [2016-11-01T12:47:53.366972 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/provenanceMetadata (60.5ms)
D, [2016-11-01T12:47:53.428595 #29163] DEBUG -- : Loaded datastream profile druid:bb021tj7970/technicalMetadata (58.1ms)
D, [2016-11-01T12:47:53.562573 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/DC (70.6ms)
D, [2016-11-01T12:47:53.625276 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/events (46.9ms)
D, [2016-11-01T12:47:54.115407 #29163] DEBUG -- : Loaded datastream list for druid:tm388wy6148 (77.7ms)
D, [2016-11-01T12:47:54.204862 #29163] DEBUG -- : Loaded datastream profile druid:tm388wy6148/RELS-EXT (87.2ms)
D, [2016-11-01T12:47:54.273573 #29163] DEBUG -- : Loaded datastream content druid:tm388wy6148/RELS-EXT (67.0ms)
D, [2016-11-01T12:47:54.334136 #29163] DEBUG -- : Loaded datastream profile druid:tm388wy6148/identityMetadata (58.9ms)
D, [2016-11-01T12:47:54.408234 #29163] DEBUG -- : Loaded datastream content druid:tm388wy6148/identityMetadata (73.7ms)
D, [2016-11-01T12:47:54.485402 #29163] DEBUG -- : Loaded datastream profile druid:tm388wy6148/rightsMetadata (73.1ms)
D, [2016-11-01T12:47:54.570421 #29163] DEBUG -- : Loaded datastream content druid:tm388wy6148/rightsMetadata (83.1ms)
D, [2016-11-01T12:47:54.643577 #29163] DEBUG -- : Loaded datastream profile druid:tm388wy6148/workflowDefinition (72.2ms)
D, [2016-11-01T12:47:54.713170 #29163] DEBUG -- : Loaded datastream content druid:tm388wy6148/workflowDefinition (68.1ms)
D, [2016-11-01T12:47:54.805927 #29163] DEBUG -- : Loaded datastream profile druid:tm388wy6148/workflowDefinition (83.2ms)
D, [2016-11-01T12:47:54.865886 #29163] DEBUG -- : Loaded datastream content druid:tm388wy6148/workflowDefinition (59.7ms)
D, [2016-11-01T12:47:55.113548 #29163] DEBUG -- : Loaded datastream list for druid:rs056hz6024 (55.1ms)
D, [2016-11-01T12:47:55.180266 #29163] DEBUG -- : Loaded datastream profile druid:rs056hz6024/RELS-EXT (65.4ms)
D, [2016-11-01T12:47:55.238932 #29163] DEBUG -- : Loaded datastream content druid:rs056hz6024/RELS-EXT (57.2ms)
D, [2016-11-01T12:47:55.295745 #29163] DEBUG -- : Loaded datastream profile druid:rs056hz6024/identityMetadata (55.4ms)
D, [2016-11-01T12:47:55.348798 #29163] DEBUG -- : Loaded datastream content druid:rs056hz6024/identityMetadata (52.6ms)
D, [2016-11-01T12:47:55.397658 #29163] DEBUG -- : Loaded datastream profile druid:rs056hz6024/workflowDefinition (46.2ms)
D, [2016-11-01T12:47:55.452877 #29163] DEBUG -- : Loaded datastream content druid:rs056hz6024/workflowDefinition (54.2ms)
D, [2016-11-01T12:47:55.520806 #29163] DEBUG -- : Loaded datastream profile druid:rs056hz6024/workflowDefinition (64.1ms)
D, [2016-11-01T12:47:55.577901 #29163] DEBUG -- : Loaded datastream content druid:rs056hz6024/workflowDefinition (56.8ms)
D, [2016-11-01T12:47:55.766051 #29163] DEBUG -- : Loaded datastream list for druid:yt984hn7118 (65.7ms)
D, [2016-11-01T12:47:55.833180 #29163] DEBUG -- : Loaded datastream profile druid:yt984hn7118/RELS-EXT (64.0ms)
D, [2016-11-01T12:47:55.923605 #29163] DEBUG -- : Loaded datastream content druid:yt984hn7118/RELS-EXT (88.7ms)
D, [2016-11-01T12:47:55.997298 #29163] DEBUG -- : Loaded datastream profile druid:yt984hn7118/identityMetadata (71.1ms)
D, [2016-11-01T12:47:56.050082 #29163] DEBUG -- : Loaded datastream content druid:yt984hn7118/identityMetadata (52.2ms)
D, [2016-11-01T12:47:56.101754 #29163] DEBUG -- : Loaded datastream profile druid:yt984hn7118/rightsMetadata (48.3ms)
D, [2016-11-01T12:47:56.158944 #29163] DEBUG -- : Loaded datastream content druid:yt984hn7118/rightsMetadata (56.0ms)
D, [2016-11-01T12:47:56.217621 #29163] DEBUG -- : Loaded datastream profile druid:yt984hn7118/workflowDefinition (58.1ms)
D, [2016-11-01T12:47:56.278404 #29163] DEBUG -- : Loaded datastream content druid:yt984hn7118/workflowDefinition (59.6ms)
D, [2016-11-01T12:47:56.402576 #29163] DEBUG -- : Loaded datastream list for druid:nb274zx7788 (60.6ms)
D, [2016-11-01T12:47:56.464145 #29163] DEBUG -- : Loaded datastream profile druid:nb274zx7788/RELS-EXT (60.6ms)
D, [2016-11-01T12:47:56.523756 #29163] DEBUG -- : Loaded datastream content druid:nb274zx7788/RELS-EXT (58.5ms)
D, [2016-11-01T12:47:56.579909 #29163] DEBUG -- : Loaded datastream profile druid:nb274zx7788/identityMetadata (54.9ms)
D, [2016-11-01T12:47:56.646835 #29163] DEBUG -- : Loaded datastream content druid:nb274zx7788/identityMetadata (66.5ms)
D, [2016-11-01T12:47:56.745033 #29163] DEBUG -- : Loaded datastream profile druid:nb274zx7788/workflowDefinition (94.7ms)
D, [2016-11-01T12:47:56.813705 #29163] DEBUG -- : Loaded datastream content druid:nb274zx7788/workflowDefinition (67.4ms)
D, [2016-11-01T12:47:56.880756 #29163] DEBUG -- : Loaded datastream profile druid:yt984hn7118/workflowDefinition (65.5ms)
D, [2016-11-01T12:47:56.943156 #29163] DEBUG -- : Loaded datastream content druid:yt984hn7118/workflowDefinition (60.3ms)
D, [2016-11-01T12:47:57.134936 #29163] DEBUG -- : Loaded datastream list for druid:yp220bx1022 (67.8ms)
D, [2016-11-01T12:47:57.197355 #29163] DEBUG -- : Loaded datastream profile druid:yp220bx1022/RELS-EXT (61.0ms)
D, [2016-11-01T12:47:57.261668 #29163] DEBUG -- : Loaded datastream content druid:yp220bx1022/RELS-EXT (63.1ms)
D, [2016-11-01T12:47:57.345993 #29163] DEBUG -- : Loaded datastream profile druid:yp220bx1022/identityMetadata (80.4ms)
D, [2016-11-01T12:47:57.426754 #29163] DEBUG -- : Loaded datastream content druid:yp220bx1022/identityMetadata (79.0ms)
D, [2016-11-01T12:47:57.492752 #29163] DEBUG -- : Loaded datastream profile druid:yp220bx1022/workflowDefinition (63.1ms)
D, [2016-11-01T12:47:57.561417 #29163] DEBUG -- : Loaded datastream content druid:yp220bx1022/workflowDefinition (66.9ms)
D, [2016-11-01T12:47:57.627659 #29163] DEBUG -- : Loaded datastream profile druid:yp220bx1022/workflowDefinition (63.5ms)
D, [2016-11-01T12:47:57.714752 #29163] DEBUG -- : Loaded datastream content druid:yp220bx1022/workflowDefinition (86.6ms)
D, [2016-11-01T12:47:57.959099 #29163] DEBUG -- : Loaded datastream list for druid:bb163sd6279 (63.9ms)
D, [2016-11-01T12:47:58.045857 #29163] DEBUG -- : Loaded datastream profile druid:bb163sd6279/RELS-EXT (85.4ms)
D, [2016-11-01T12:47:58.122681 #29163] DEBUG -- : Loaded datastream content druid:bb163sd6279/RELS-EXT (74.8ms)
D, [2016-11-01T12:47:58.189167 #29163] DEBUG -- : Loaded datastream profile druid:bb163sd6279/identityMetadata (64.3ms)
D, [2016-11-01T12:47:58.247552 #29163] DEBUG -- : Loaded datastream content druid:bb163sd6279/identityMetadata (57.9ms)
D, [2016-11-01T12:47:58.316161 #29163] DEBUG -- : Loaded datastream profile druid:bb163sd6279/workflowDefinition (62.0ms)
D, [2016-11-01T12:47:58.413872 #29163] DEBUG -- : Loaded datastream content druid:bb163sd6279/workflowDefinition (95.8ms)
D, [2016-11-01T12:47:58.503756 #29163] DEBUG -- : Loaded datastream profile druid:bb163sd6279/workflowDefinition (73.8ms)
D, [2016-11-01T12:47:58.595635 #29163] DEBUG -- : Loaded datastream content druid:bb163sd6279/workflowDefinition (91.4ms)
D, [2016-11-01T12:47:58.758938 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/contentMetadata (79.6ms)
D, [2016-11-01T12:47:58.826862 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/rightsMetadata (66.4ms)
D, [2016-11-01T12:47:58.910200 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/descMetadata (73.6ms)
D, [2016-11-01T12:47:58.988990 #29163] DEBUG -- : Loaded datastream content druid:bb021tj7970/versionMetadata (66.8ms)
D, [2016-11-01T12:47:59.385424 #29163] DEBUG -- : Loaded datastream list for druid:sq161jk2248 (68.7ms)
D, [2016-11-01T12:47:59.456260 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/RELS-EXT (67.1ms)
D, [2016-11-01T12:47:59.506430 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/RELS-EXT (49.1ms)
D, [2016-11-01T12:47:59.557526 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/identityMetadata (49.3ms)
D, [2016-11-01T12:47:59.633254 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/identityMetadata (75.2ms)
D, [2016-11-01T12:47:59.710357 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/rightsMetadata (65.0ms)
D, [2016-11-01T12:47:59.774019 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/rightsMetadata (62.2ms)
D, [2016-11-01T12:47:59.846608 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/descMetadata (69.2ms)
D, [2016-11-01T12:47:59.919912 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/descMetadata (71.2ms)
D, [2016-11-01T12:47:59.990437 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/workflows (69.1ms)
D, [2016-11-01T12:48:00.066444 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/versionMetadata (74.5ms)
D, [2016-11-01T12:48:00.163065 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/versionMetadata (94.8ms)
D, [2016-11-01T12:48:00.257070 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/administrativeMetadata (89.2ms)
D, [2016-11-01T12:48:00.329782 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/administrativeMetadata (71.3ms)
D, [2016-11-01T12:48:00.429182 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/roleMetadata (83.6ms)
D, [2016-11-01T12:48:00.498176 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/roleMetadata (67.4ms)
D, [2016-11-01T12:48:00.569815 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/defaultObjectRights (68.6ms)
D, [2016-11-01T12:48:00.644765 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/defaultObjectRights (73.4ms)
D, [2016-11-01T12:48:00.714488 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/versionMetadata (65.2ms)
D, [2016-11-01T12:48:00.791023 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/workflows (75.0ms)
D, [2016-11-01T12:48:00.870766 #29163] DEBUG -- : Loaded datastream profile druid:sq161jk2248/descMetadata (79.2ms)
D, [2016-11-01T12:48:00.948644 #29163] DEBUG -- : Loaded datastream content druid:sq161jk2248/descMetadata (77.1ms)
D, [2016-11-01T12:48:01.203300 #29163] DEBUG -- : Loaded datastream list for druid:xh235dd9059 (67.7ms)
D, [2016-11-01T12:48:01.298757 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/RELS-EXT (93.3ms)
D, [2016-11-01T12:48:01.401447 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/RELS-EXT (100.5ms)
D, [2016-11-01T12:48:01.493723 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/identityMetadata (89.0ms)
D, [2016-11-01T12:48:01.574489 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/identityMetadata (80.2ms)
D, [2016-11-01T12:48:01.668611 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/workflows (87.4ms)
D, [2016-11-01T12:48:01.763850 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/rightsMetadata (93.1ms)
D, [2016-11-01T12:48:01.857778 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/rightsMetadata (91.8ms)
D, [2016-11-01T12:48:01.939757 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/descMetadata (79.4ms)
D, [2016-11-01T12:48:02.054310 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/descMetadata (112.1ms)
D, [2016-11-01T12:48:02.152682 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/versionMetadata (94.5ms)
D, [2016-11-01T12:48:02.273964 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/versionMetadata (118.8ms)
D, [2016-11-01T12:48:02.352637 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/versionMetadata (60.3ms)
D, [2016-11-01T12:48:02.406995 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/workflows (53.0ms)
D, [2016-11-01T12:48:02.457444 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/descMetadata (50.1ms)
D, [2016-11-01T12:48:02.509768 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/descMetadata (50.8ms)
D, [2016-11-01T12:48:02.668708 #29163] DEBUG -- : Loaded datastream list for druid:xh235dd9059 (75.2ms)
D, [2016-11-01T12:48:02.726747 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/RELS-EXT (56.6ms)
D, [2016-11-01T12:48:02.797315 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/RELS-EXT (62.9ms)
D, [2016-11-01T12:48:02.868425 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/workflows (68.8ms)
D, [2016-11-01T12:48:02.924152 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/descMetadata (55.1ms)
D, [2016-11-01T12:48:02.997302 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/descMetadata (72.8ms)
D, [2016-11-01T12:48:03.418446 #29163] DEBUG -- : Loaded datastream list for druid:xh235dd9059 (49.4ms)
D, [2016-11-01T12:48:03.483181 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/RELS-EXT (63.3ms)
D, [2016-11-01T12:48:03.551300 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/RELS-EXT (67.0ms)
D, [2016-11-01T12:48:03.622441 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/workflows (69.1ms)
D, [2016-11-01T12:48:03.798613 #29163] DEBUG -- : Loaded datastream list for druid:xh235dd9059 (63.4ms)
D, [2016-11-01T12:48:03.855776 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/RELS-EXT (55.8ms)
D, [2016-11-01T12:48:03.919276 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/RELS-EXT (62.2ms)
D, [2016-11-01T12:48:03.992324 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/workflows (67.8ms)
D, [2016-11-01T12:48:04.060731 #29163] DEBUG -- : Loaded datastream profile druid:xh235dd9059/identityMetadata (68.2ms)
D, [2016-11-01T12:48:04.134106 #29163] DEBUG -- : Loaded datastream content druid:xh235dd9059/identityMetadata (72.6ms)
=> #<Benchmark::Tms:0x00000003001e98
@cstime=0.0,
@cutime=0.0,
@label="",
@real=11.552672865000204,
@stime=0.3799999999999999,
@total=7.06,
@utime=6.68>
Below is an example of the HTTP GET requests made to Fedora a Dor::Item via ActiveRecord and calling .to_solr -- there are 16 GET calls:
hs309xt0215?format=xml
hs309xt0215/datastreams?profiles=true&format=xml
hs309xt0215/datastreams/identityMetadata?format=xml
hs309xt0215/datastreams/workflows?format=xml
hs309xt0215/datastreams/RELS-EXT/content
hs309xt0215/datastreams/contentMetadata?format=xml
hs309xt0215/datastreams/rightsMetadata?format=xml
hs309xt0215/datastreams/descMetadata?format=xml
hs309xt0215/datastreams/provenanceMetadata?format=xml
hs309xt0215/datastreams/technicalMetadata?format=xml
hs309xt0215/datastreams/versionMetadata?format=xml
hs309xt0215/datastreams/geoMetadata?format=xml
hs309xt0215/datastreams/embargoMetadata?format=xml
hs309xt0215/datastreams/DC/content
hs309xt0215/datastreams/events/content
hs309xt0215/datastreams/embargoMetadata/content
GET /workflow/dor/objects/druid:hs309xt0215/workflows/ HTTP/1.1" 200 1884
GET /workflow/dor/objects/druid:hs309xt0215/lifecycle HTTP/1.1" 200 122
GET /workflow/dor/objects/druid:hs309xt0215/lifecycle HTTP/1.1" 200 122
In production, over the last 2 days (11/1-2), we're seeing the following average throughput:
-
fedora.apim.updateis getting ~500 messages/hour on the "a" ActiveMQ node. These are all forwarded to the reindexing queue -- specifically, theVirtualTopic.${headers.DorHost}.object.changedtopic. -
fedora.apim.accessis getting ~16,000 messages/hour on the "a" ActiveMQ node. These are all dropped as they are enqueued but not consumed. As of 11/19/16, we've disabled these messages.
Here is a snapshot of the outbound update messages from ~45 minutes from the production workflow service (20 messages for 17 objects):
druid:hs309xt0215
druid:hs309xt0215
druid:hs309xt0215
druid:kh379rr6180
druid:jn398tk0439
druid:nz716yf0097
druid:fg261yb9612
druid:bk560pg8201
druid:cf558zv1957
druid:km409rc0851
druid:nf483fx5396
druid:qk306hh1567
druid:rz920tb9915
druid:tb213bx7240
druid:tx955qf2470
druid:wt877mk7756
druid:zw407ty0272
druid:jr137vy7651
druid:jr137vy7651
druid:cs723xp2463