search

Geonovum / sospilot

Sensor Observation Service (SOS) and data management for Air Quality data from RIVM The Netherlands
GNU General Public License v3.0
9 stars 5 forks source link

SOS InsertObservation request duration increases as SOS database grows #1

Closed justb4 closed 10 years ago

justb4 commented 10 years ago

This is observed in the timing data from the cron job that publishes rivm_lml measurements via InsertObservation to the SOS server. Each half hour max 1000 measurements are published. In the first rounds about 5 Observations per/sec could be published, see logging data:

2014-06-09 15:47:34,854 httpoutput INFO Response status: code=200 msg=OK
2014-06-09 15:47:35,123 httpoutput INFO Response status: code=200 msg=OK
2014-06-09 15:47:35,450 httpoutput INFO Response status: code=200 msg=OK
2014-06-09 15:47:35,668 httpoutput INFO Response status: code=200 msg=OK
2014-06-09 15:47:35,873 httpoutput INFO Response status: code=200 msg=OK
2014-06-09 15:47:36,088 httpoutput INFO Response status: code=200 msg=OK

After a few days with about 100000 observations in the SOS database, this has slowed down to one insert taking between 1 and 2 seconds:

2014-06-11 17:02:57,890 httpoutput INFO Response status: code=200 msg=OK
2014-06-11 17:02:59,328 httpoutput INFO Response status: code=200 msg=OK
2014-06-11 17:03:00,633 httpoutput INFO Response status: code=200 msg=OK
2014-06-11 17:03:01,900 httpoutput INFO Response status: code=200 msg=OK
2014-06-11 17:03:03,255 httpoutput INFO Response status: code=200 msg=OK
justb4 commented 10 years ago

This gives an overview in time, cron runs every half hour. Each run publishes 1000 observations/records. About 10-20 secords is added for each extra 1000 records in the database.

2014-06-12 15:02:18,888 util INFO Timer end: total ETL time=137.0 sec
2014-06-12 15:32:40,700 util INFO Timer end: total ETL time=146.0 sec
2014-06-12 16:02:45,658 util INFO Timer end: total ETL time=163.0 sec
2014-06-12 16:32:56,394 util INFO Timer end: total ETL time=173.0 sec
2014-06-12 17:04:01,339 util INFO Timer end: total ETL time=238.0 sec
2014-06-12 17:33:56,256 util INFO Timer end: total ETL time=233.0 sec
2014-06-12 18:04:04,643 util INFO Timer end: total ETL time=242.0 sec
2014-06-12 18:34:12,131 util INFO Timer end: total ETL time=249.0 sec
2014-06-12 19:04:19,237 util INFO Timer end: total ETL time=257.0 sec
2014-06-12 19:34:42,109 util INFO Timer end: total ETL time=279.0 sec
2014-06-12 20:04:46,885 util INFO Timer end: total ETL time=285.0 sec
2014-06-12 20:34:59,242 util INFO Timer end: total ETL time=296.0 sec
2014-06-12 21:05:07,489 util INFO Timer end: total ETL time=305.0 sec
2014-06-12 21:35:28,332 util INFO Timer end: total ETL time=325.0 sec
2014-06-12 22:05:27,600 util INFO Timer end: total ETL time=325.0 sec
2014-06-12 22:35:33,300 util INFO Timer end: total ETL time=330.0 sec
2014-06-12 23:05:57,264 util INFO Timer end: total ETL time=355.0 sec
2014-06-12 23:35:49,307 util INFO Timer end: total ETL time=346.0 sec
2014-06-13 00:06:15,163 util INFO Timer end: total ETL time=373.0 sec
2014-06-13 00:36:08,127 util INFO Timer end: total ETL time=365.0 sec
2014-06-13 01:06:18,585 util INFO Timer end: total ETL time=376.0 sec
2014-06-13 01:36:22,030 util INFO Timer end: total ETL time=379.0 sec
2014-06-13 02:06:42,057 util INFO Timer end: total ETL time=400.0 sec
2014-06-13 02:36:41,523 util INFO Timer end: total ETL time=399.0 sec
2014-06-13 03:06:56,759 util INFO Timer end: total ETL time=414.0 sec
2014-06-13 03:37:08,135 util INFO Timer end: total ETL time=425.0 sec
2014-06-13 04:07:08,242 util INFO Timer end: total ETL time=426.0 sec
2014-06-13 04:37:18,963 util INFO Timer end: total ETL time=436.0 sec
2014-06-13 05:07:27,690 util INFO Timer end: total ETL time=446.0 sec
2014-06-13 05:37:36,612 util INFO Timer end: total ETL time=453.0 sec
2014-06-13 06:07:50,963 util INFO Timer end: total ETL time=468.0 sec
2014-06-13 06:38:04,450 util INFO Timer end: total ETL time=482.0 sec
2014-06-13 07:08:24,803 util INFO Timer end: total ETL time=502.0 sec
2014-06-13 07:38:17,122 util INFO Timer end: total ETL time=495.0 sec
2014-06-13 08:08:48,487 util INFO Timer end: total ETL time=526.0 sec
2014-06-13 08:38:48,889 util INFO Timer end: total ETL time=526.0 sec
2014-06-13 09:09:03,958 util INFO Timer end: total ETL time=542.0 sec
2014-06-13 09:39:11,858 util INFO Timer end: total ETL time=549.0 sec
2014-06-13 10:09:14,740 util INFO Timer end: total ETL time=552.0 sec
2014-06-13 10:39:25,239 util INFO Timer end: total ETL time=562.0 sec
2014-06-13 11:09:50,132 util INFO Timer end: total ETL time=588.0 sec
2014-06-13 11:40:08,400 util INFO Timer end: total ETL time=606.0 sec
2014-06-13 12:10:07,351 util INFO Timer end: total ETL time=605.0 sec
2014-06-13 12:40:18,089 util INFO Timer end: total ETL time=615.0 sec
2014-06-13 13:10:27,984 util INFO Timer end: total ETL time=626.0 sec
2014-06-13 13:40:38,592 util INFO Timer end: total ETL time=636.0 sec
2014-06-13 14:10:52,312 util INFO Timer end: total ETL time=650.0 sec
2014-06-13 14:40:54,992 util INFO Timer end: total ETL time=652.0 sec
2014-06-13 15:11:17,715 util INFO Timer end: total ETL time=676.0 sec
2014-06-13 15:41:14,614 util INFO Timer end: total ETL time=672.0 sec
justb4 commented 10 years ago

This was solved with a patch by 52N:

    -rw-r--r-- 1 tomcat7 tomcat7   72842 Jul  1 16:41 cache-4.0.2-SNAPSHOT.jar

See mail from Simon Jirka on July 1, 2014:

Hi Just,

as mentioned last week, the problem with the SOS getting slower when the number of observation increases should be solved. Here is the update to fix this problem.

You can continue to use the existing SOS instance and database. It is only necessary to copy/overwrite the attached file to the lib folder of you SOS instance.

Here are the steps to apply the changes to your SOS instance: