Opened 7 years ago

Last modified 7 years ago

#1660 closed defect

petascope NioEventLoop TRACE logs — at Version 2

Reported by: Dimitar Misev Owned by: Bang Pham Huu
Priority: major Milestone: 9.5
Component: petascope Version: development
Keywords: Cc: Peter Baumann
Complexity: Medium

Description (last modified by Dimitar Misev)

The startup log can be improved, here's a suggestion: https://www.diffchecker.com/K2KSwtdk

Below, 66 what? ms? I would word it as rasql query executed in 66 ms.

 DEBUG [11:42:46] RasUtil@229: Total time for rasql: 66

Here I see three identical logs for the rasql query basically. Only one is enough (RasUtil@142 I guess), the others should be removed:

 DEBUG [11:42:49] KVPWCSProcessCoverageHandler@114: Executing rasql query: SELECT encode(c[0:885,0:710], "png" , "{\"geoReference\":{\"crs\":\"EPSG:4326\",\"bbox\":{\"xmin\":111.975,\"ymin\":-44.525,\"xmax\":156.275,\"ymax\":-8.975}
}}") FROM test_mean_summer_airtemp AS c
 DEBUG [11:42:49] RasUtil@92: Execute rasql query 'SELECT encode(c[0:885,0:710], "png" , "{\"geoReference\":{\"crs\":\"EPSG:4326\",\"bbox\":{\"xmin\":111.975,\"ymin\":-44.525,\"xmax\":156.275,\"ymax\":-8.975}}}") FROM test_mean_summ
er_airtemp AS c'.
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@603a636e
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@591359e9
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3fccc3a4
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3d6abc0a
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@e7899da
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@4de745ed
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@146f6e16
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@7c0d1a7d
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@36f1ea6f
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@41ce0971
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@2e3ed080
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3af4f9c8
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3efce6b
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@32dbdae6
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@6ab9b6ed
 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@771e28cb
 TRACE [11:42:49] RasUtil@142: Executing query SELECT encode(c[0:885,0:710], "png" , "{\"geoReference\":{\"crs\":\"EPSG:4326\",\"bbox\":{\"xmin\":111.975,\"ymin\":-44.525,\"xmax\":156.275,\"ymax\":-8.975}}}") FROM test_mean_summer_a
irtemp AS c

There are too many of these logs, they should be blocked somehow (e.g. configure properly log4j of the libraries used in petascope):

 TRACE [11:42:49] NioEventLoop@46: instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@771e28cb
 ...
 DEBUG [11:42:49] PoolThreadCache@81: Freed 1 thread-local buffer(s) from thread: threadDeathWatcher-3-2

There's duplication about the 'coverage id read from cache' (I think that log statement could be completely removed, it's not very useful at all):

 DEBUG [11:42:50] PetascopeController@90: Received request: coverageId=test_mean_summer_airtemp&format=image/png&request=GetCoverage&service=WCS&version=2.0.1
 DEBUG [11:42:50] AbstractHandler@90: Found the request handler: petascope.controller.handler.service.KVPWCSServiceHandler
 DEBUG [11:42:50] CoverageRepostioryService@119: Coverage id 'test_mean_summer_airtemp' is read from cache.
 DEBUG [11:42:50] ResponseService@128: Generated a single WCPS query from WCS request: for c in (test_mean_summer_airtemp) return encode(c[Lat(-44.525:-8.975), Long(111.975:156.275)], "png")
 DEBUG [11:42:50] CoverageRepostioryService@119: Coverage id 'test_mean_summer_airtemp' is read from cache.

This should not be INFO:

  INFO [11:40:17] TypeRegistry@202: Succesfully initiated the type registry. Contents: {RGBSet...

best split it like this (notice also some fixed typos!):

  INFO [11:40:17] TypeRegistry@202: Successfully initialized the type registry. 
  TRACE [11:40:17] TypeRegistry@202: Contents: {RGBSet...

Change History (2)

comment:1 by Dimitar Misev, 7 years ago

Component: undecidedpetascope
Milestone: 9.5
Owner: set to Bang Pham Huu
Status: newassigned

comment:2 by Dimitar Misev, 7 years ago

Cc: Peter Baumann added
Description: modified (diff)
Note: See TracTickets for help on using tickets.