Ingestion with wcst_import is slow in the systemtest

[Dimitar Misev]

rasql executes updates in less than 100ms, but the update queries from petascope come in very slowly, sometimes with a ~1 second delay.
We need to investigate and understand why this happens, at first sight it doesn't make sense.

Here's an excerpt from the rasserver log, which shows that there can be significant delays between successive updates.

 [INFO] - 29/05/2017 11:55:07.310132: Connected successfully to '/d/rasdata/RASBASE'
 [INFO] - 29/05/2017 11:55:07.310373: Request: 'UPDATE test_float_fractional_time_unixtime SET test_float_fractional_time_unixtime[7,0:40,0:1] ASSIGN shift(decode(<[0:0] 1c>, "GDAL", "{\"filePaths\":[\"/home/dimitar/rasdaman/enterprise/src/systemtest/testcases_services/test_all_wcst_import/test_data/wcps_float_fractional_time_unixtime/T_[1377654920.982].tif\"]}"), [0,0]) WHERE oid(test_float_fractional_time_unixtime) = 13313'...
 [INFO] - 29/05/2017 11:55:07.310379: parsing...
 [INFO] - 29/05/2017 11:55:07.310443: checking semantics...
 [INFO] - 29/05/2017 11:55:07.310516: evaluating...
 [INFO] - 29/05/2017 11:55:07.310743: ok
 [INFO] - 29/05/2017 11:55:08.32530: Connected successfully to '/d/rasdata/RASBASE'
 [INFO] - 29/05/2017 11:55:08.32991: Request: 'select sdom(c) from test_float_fractional_time_unixtime AS c where oid(c) = 13313'...
 [INFO] - 29/05/2017 11:55:08.32999: parsing...
 [INFO] - 29/05/2017 11:55:08.33054: checking semantics...
 [INFO] - 29/05/2017 11:55:08.33127: optimizing (level 3)...
 [INFO] - 29/05/2017 11:55:08.33139: evaluating...
 [INFO] - 29/05/2017 11:55:08.33238: ok, result type 'set<minterval>', 1 element(s).
 [INFO] - 29/05/2017 11:55:08.33247: ok
 [INFO] - 29/05/2017 11:55:08.43560: Connected successfully to '/d/rasdata/RASBASE'
 [INFO] - 29/05/2017 11:55:08.43831: Request: 'UPDATE test_float_fractional_time_unixtime SET test_float_fractional_time_unixtime[8,0:40,0:1] ASSIGN shift(decode(<[0:0] 1c>, "GDAL", "{\"filePaths\":[\"/home/dimitar/rasdaman/enterprise/src/systemtest/testcases_services/test_all_wcst_import/test_data/wcps_float_fractional_time_unixtime/T_[1378654920.98].tif\"]}"), [0,0]) WHERE oid(test_float_fractional_time_unixtime) = 13313'...
 [INFO] - 29/05/2017 11:55:08.43839: parsing...
 [INFO] - 29/05/2017 11:55:08.43904: checking semantics...
 [INFO] - 29/05/2017 11:55:08.43977: evaluating...
 [INFO] - 29/05/2017 11:55:08.44210: ok
 [INFO] - 29/05/2017 11:55:08.99056: Connected successfully to '/d/rasdata/RASBASE'
 [INFO] - 29/05/2017 11:55:08.99462: Request: 'select sdom(c) from test_float_fractional_time_unixtime AS c where oid(c) = 13313'...
 [INFO] - 29/05/2017 11:55:08.99469: parsing...
 [INFO] - 29/05/2017 11:55:08.99524: checking semantics...
 [INFO] - 29/05/2017 11:55:08.99599: optimizing (level 3)...
 [INFO] - 29/05/2017 11:55:08.99612: evaluating...
 [INFO] - 29/05/2017 11:55:08.99685: ok, result type 'set<minterval>', 1 element(s).
 [INFO] - 29/05/2017 11:55:08.99693: ok
 [INFO] - 29/05/2017 11:55:08.109914: Connected successfully to '/d/rasdata/RASBASE'
 [INFO] - 29/05/2017 11:55:08.110164: Request: 'UPDATE test_float_fractional_time_unixtime SET test_float_fractional_time_unixtime[9,0:40,0:1] ASSIGN shift(decode(<[0:0] 1c>, "GDAL", "{\"filePaths\":[\"/home/dimitar/rasdaman/enterprise/src/systemtest/testcases_services/test_all_wcst_import/test_data/wcps_float_fractional_time_unixtime/T_[1380619710.35].tif\"]}"), [0,0]) WHERE oid(test_float_fractional_time_unixtime) = 13313'...
 [INFO] - 29/05/2017 11:55:08.110172: parsing...
 [INFO] - 29/05/2017 11:55:08.110237: checking semantics...
 [INFO] - 29/05/2017 11:55:08.110313: evaluating...
 [INFO] - 29/05/2017 11:55:08.110568: ok

[Bang Pham Huu]

I did the test for new Petascope which is version 9.5, the result in Petascope's log shows that the time in rasserver log is not correct

There are 6 requests to UpdateCoverage from same file to Petascope's log.

​https://pastebin.com/YVBs2v71

and there are same 6 requests to rasserver's log

​https://pastebin.com/ma3USjjA

In general, Petascope takes around 400 milliseconds to handle 1 request and next 150 milliseconds to handle next request and the log in petascope shows correct time intervals consistently.

But log in rasserver shows not correct time intervals, for example:

first request in Petascope at: start: 01-06-2017 14:47:15.921
and first request in rasserver at: 01/06/2017 14:47:15.330427

and second request in Petascope at: 01-06-2017 14:47:16.381
and second request in rasserver at: 01/06/2017 14:47:16.143018

and third request in Petascope at: 01-06-2017 14:47:16.771
and third request in rasserver at: 01/06/2017 14:47:16.273381

How could rasserver log's before the time of Petascope's log to start a first and third request?

The difference in rasserver's log from first to second is around 1 second and second to third is only 130 millisecond and this made a false impression about the time should be exectuted (i.e: around 400 milliseconds).

I can say that Petascope works well with consistent time intervals between requests.

[Dimitar Misev]

So the rasserver log is not very correct then and we cannot rely on it.

What you could do is add a timer in the RasUtil class where petascope executes the rasql query. Then add all times for rasql queries and subtract from the total execution time to get the petascope time.

[Bang Pham Huu]

​https://pastebin.com/msdbPpAf

The time for the method in petascope is around 16 milliseconds and for rasql is around 300 milliseconds.

1. time for rasql: 245

Total milliseconds: 267

2. time for rasql: 261

Total milliseconds: 275

3. time for rasql: 229

Total milliseconds: 243

4. time for rasql: 260

Total milliseconds: 274

5. time for rasql: 262

Total milliseconds: 276

6. time for rasql: 256

Total milliseconds: 269