Uploaded image for project: 'Dev - Nexus Repo'
  1. Dev - Nexus Repo
  2. NEXUS-13432

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

    XMLWordPrintable

    Details

      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

      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.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              dsauble Daniel Sauble
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Peter Lynch
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title