asset download count feature contributes log noise and heap memory spike every 24 hrs when deleting old download counts

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

1. Edit <data-dir>/etc/nexus.properties
2. Add a new line at the end of that file that looks like this: nexus.assetdownloads.enabled=false
3. 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

An article has been added discussing this.