Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Major
-
Resolution: Fixed
-
Affects Version/s: 3.3.0, 3.3.1, 3.3.2
-
Fix Version/s: 3.4.0
-
Component/s: Repository Health Check
-
Labels:
Description
There are reports of logs filled with thousands of messages such as these at the same time every day:
2017-06-17 00:57:40,504+0200 INFO [pool-20-thread-1] anonymous com.orientechnologies.orient.core.storage.impl.local.paginated.wal.OLogSegment - $ANSI{green {db=component}} Max cache limit is reached (3000 vs. 11673), sync flush is performed 2017-06-17 00:57:40,504+0200 ERROR [OrientDB WAL Flush Task (component)] *SYSTEM com.orientechnologies.orient.core.storage.impl.local.paginated.wal.OLogSegment$FlushTask - Error during WAL background flush java.lang.IllegalArgumentException: null at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:278) [na:1.8.0_131] at com.orientechnologies.orient.core.storage.impl.local.paginated.wal.OLogSegment$FlushTask.commitLog(OLogSegment.java:233) [com.orientechnologies.orientdb-core:2.2.18] at com.orientechnologies.orient.core.storage.impl.local.paginated.wal.OLogSegment$FlushTask.run(OLogSegment.java:134) [com.orientechnologies.orientdb-core:2.2.18] at com.orientechnologies.common.concur.executors.SubExecutorService$RunnableTask.run(SubExecutorService.java:296) [com.orientechnologies.orientdb-core:2.2.18] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_131] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_131] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_131] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Shortly before these messages start, we see this in the log:
2017-06-17 00:51:53,525+0200 INFO [pool-20-thread-1] anonymous com.orientechnologies.common.profiler.OProfilerStub - $ANSI{green {db=component}} [TIP] Query 'SELECT FROM assetdownloadcount WHERE node_id = "616CB638-51579A2A-47959392-B47F6818-4BCF3D04" AND date_type = :dateType AND date < date('2017-05-18 00:00:00.000', 'yyyy-MM-dd HH:mm:ss.SSS')' returned a result set with more than 10000 records. Check if you really need all these records, or reduce the resultset by using a LIMIT to improve both performance and used RAM
Of note the huge memory spike at nearly the same time around these log messages every 24 hours.
Problems
- heap memory spike every 24 hours at the same time, sometimes leading to OutOfMemory, depending on the overall system load at the time of the spike
- many log statements "Max cache limit reached"
- many log statements "OLogSegment$FlushTask - Error during WAL background flush java.lang.IllegalArgumentException: null"
Diagnosis
Every 24 hrs, there are some database queries being performed related to asset download counts that are doing full database table scans and performing queries which had no upper record limit set on their transaction record count.
The resulting spurious log messages are triggered by these poor performing queries. Further, the IllegalArgumentException being logged is a bug in OrientDB code.
Workaround: Disabling Asset Download Counts Feature
- Edit <data-dir>/etc/nexus.properties
- Add a new line at the end of that file that looks like this: nexus.assetdownloads.enabled=false
- Restart Nexus for the property change to have effect.
Expected
- asset download count feature performance should result in negligible performance regression when enabled and not trigger spurious log messages
Reference
Attachments
Issue Links
- is related to
-
NEXUS-13087 caching asset download counts under high unique request volume can lead to OutOfMemoryError and instability
-
- Closed
-