[tor-bugs] #19249 [Metrics/Onionoo]: Onionoo server runs out of memory when importing a full month of data

Tor Bug Tracker & Wiki blackhole at torproject.org
Thu Jun 2 16:35:40 UTC 2016 

#19249: Onionoo server runs out of memory when importing a full month of data
---------------------------------+-----------------
     Reporter:  karsten          |      Owner:
         Type:  defect           |     Status:  new
     Priority:  Medium           |  Milestone:
    Component:  Metrics/Onionoo  |    Version:
     Severity:  Normal           |   Keywords:
Actual Points:                   |  Parent ID:
       Points:                   |   Reviewer:
      Sponsor:                   |
---------------------------------+-----------------
 I had to re-import all of May on the Onionoo mirror because it was offline
 for more than three days.  Now it's running out of memory in the shut-down
 process.  Logs and exception below:

 {{{
 2016-06-01 09:30:33,944 INFO o.t.o.cron.Main:92 Going to run one-time
 updater ...
 2016-06-01 09:30:34,002 INFO o.t.o.cron.Main:130 Initializing.
 2016-06-01 09:30:34,005 INFO o.t.o.cron.Main:133 Acquired lock
 2016-06-01 09:30:34,005 DEBUG o.t.o.cron.Main:152 Started update ...
 2016-06-01 09:30:34,007 INFO o.t.o.cron.Main:155 Initialized descriptor
 source
 2016-06-01 09:30:34,012 INFO o.t.o.cron.Main:159 Initialized document
 store
 2016-06-01 09:30:34,029 INFO o.t.o.cron.Main:163 Initialized status update
 runner
 2016-06-01 09:30:34,040 INFO o.t.o.cron.Main:168 Initialized document
 writer runner
 2016-06-01 09:30:34,041 INFO o.t.o.cron.Main:176 Downloading descriptors.
 2016-06-01 09:30:34,041 INFO o.t.o.u.DescriptorSource:64 Loading:
 RELAY_CONSENSUSES
 2016-06-01 09:33:02,861 INFO o.t.o.u.DescriptorSource:64 Loading:
 RELAY_SERVER_DESCRIPTORS
 2016-06-01 09:35:39,639 INFO o.t.o.u.DescriptorSource:64 Loading:
 RELAY_EXTRA_INFOS
 2016-06-01 09:38:10,562 INFO o.t.o.u.DescriptorSource:64 Loading:
 EXIT_LISTS
 2016-06-01 09:38:51,159 INFO o.t.o.u.DescriptorSource:64 Loading:
 BRIDGE_STATUSES
 2016-06-01 09:40:29,716 INFO o.t.o.u.DescriptorSource:64 Loading:
 BRIDGE_SERVER_DESCRIPTORS
 2016-06-01 09:41:58,737 INFO o.t.o.u.DescriptorSource:64 Loading:
 BRIDGE_EXTRA_INFOS
 2016-06-01 09:43:44,958 INFO o.t.o.cron.Main:184 Reading descriptors.
 2016-06-01 09:43:44,959 INFO o.t.o.u.DescriptorSource:153 Reading archived
 descriptors...
 2016-06-02 02:51:09,249 INFO o.t.o.u.DescriptorSource:200 Read archived
 descriptors
 2016-06-02 02:51:09,249 DEBUG o.t.o.u.DescriptorSource:84 Reading recent
 RELAY_SERVER_DESCRIPTORS ...
 2016-06-02 02:53:01,224 INFO o.t.o.u.DescriptorSource:129 Read recent
 relay server descriptors
 2016-06-02 02:53:01,224 DEBUG o.t.o.u.DescriptorSource:88 Reading recent
 RELAY_EXTRA_INFOS ...
 2016-06-02 03:31:50,889 INFO o.t.o.u.DescriptorSource:132 Read recent
 relay extra-info descriptors
 2016-06-02 03:31:50,890 DEBUG o.t.o.u.DescriptorSource:91 Reading recent
 EXIT_LISTS ...
 2016-06-02 03:32:13,478 INFO o.t.o.u.DescriptorSource:135 Read recent exit
 lists
 2016-06-02 03:32:13,479 DEBUG o.t.o.u.DescriptorSource:94 Reading recent
 RELAY_CONSENSUSES ...
 2016-06-02 08:29:52,761 INFO o.t.o.u.DescriptorSource:126 Read recent
 relay network consensuses
 2016-06-02 08:29:52,765 DEBUG o.t.o.u.DescriptorSource:97 Reading recent
 BRIDGE_SERVER_DESCRIPTORS ...
 2016-06-02 08:31:32,294 INFO o.t.o.u.DescriptorSource:141 Read recent
 bridge server descriptors
 2016-06-02 08:31:32,295 DEBUG o.t.o.u.DescriptorSource:101 Reading recent
 BRIDGE_EXTRA_INFOS ...
 2016-06-02 09:22:29,247 INFO o.t.o.u.DescriptorSource:144 Read recent
 bridge extra-info descriptors
 2016-06-02 09:22:29,247 DEBUG o.t.o.u.DescriptorSource:104 Reading recent
 BRIDGE_STATUSES ...
 2016-06-02 09:23:44,681 INFO o.t.o.u.DescriptorSource:138 Read recent
 bridge network statuses
 2016-06-02 09:23:44,682 INFO o.t.o.cron.Main:186 Updating internal status
 files.
 2016-06-02 09:23:44,682 DEBUG o.t.o.u.StatusUpdateRunner:36 Begin update
 of NodeDetailsStatusUpdater
 2016-06-02 09:25:02,021 INFO o.t.o.u.NodeDetailsStatusUpdater:379 Read
 node statuses
 2016-06-02 09:25:12,500 INFO o.t.o.u.NodeDetailsStatusUpdater:381 Started
 reverse domain name lookups
 2016-06-02 09:31:29,006 INFO o.t.o.u.NodeDetailsStatusUpdater:383 Looked
 up cities and ASes
 2016-06-02 09:31:29,112 INFO o.t.o.u.NodeDetailsStatusUpdater:385
 Calculated path selection probabilities
 2016-06-02 09:31:29,224 INFO o.t.o.u.NodeDetailsStatusUpdater:387 Computed
 effective and extended families
 2016-06-02 09:31:29,252 INFO o.t.o.u.NodeDetailsStatusUpdater:389 Finished
 reverse domain name lookups
 2016-06-02 09:34:37,918 INFO o.t.o.u.NodeDetailsStatusUpdater:391 Updated
 node and details statuses
 2016-06-02 09:34:37,918 INFO o.t.o.u.StatusUpdateRunner:38
 NodeDetailsStatusUpdater updated status files
 2016-06-02 09:34:37,918 DEBUG o.t.o.u.StatusUpdateRunner:36 Begin update
 of BandwidthStatusUpdater
 2016-06-02 09:34:37,918 INFO o.t.o.u.StatusUpdateRunner:38
 BandwidthStatusUpdater updated status files
 2016-06-02 09:34:37,918 DEBUG o.t.o.u.StatusUpdateRunner:36 Begin update
 of WeightsStatusUpdater
 2016-06-02 09:34:37,918 INFO o.t.o.u.StatusUpdateRunner:38
 WeightsStatusUpdater updated status files
 2016-06-02 09:34:37,919 DEBUG o.t.o.u.StatusUpdateRunner:36 Begin update
 of ClientsStatusUpdater
 2016-06-02 09:47:57,798 INFO o.t.o.u.StatusUpdateRunner:38
 ClientsStatusUpdater updated status files
 2016-06-02 09:47:57,799 DEBUG o.t.o.u.StatusUpdateRunner:36 Begin update
 of UptimeStatusUpdater
 2016-06-02 10:28:41,049 INFO o.t.o.u.StatusUpdateRunner:38
 UptimeStatusUpdater updated status files
 2016-06-02 10:28:41,049 INFO o.t.o.cron.Main:194 Updating document files.
 2016-06-02 10:28:41,049 DEBUG o.t.o.w.DocumentWriterRunner:28 Writing
 SummaryDocumentWriter
 2016-06-02 10:29:03,109 INFO o.t.o.w.SummaryDocumentWriter:97 Wrote
 summary document files
 2016-06-02 10:29:03,110 DEBUG o.t.o.w.DocumentWriterRunner:28 Writing
 DetailsDocumentWriter
 2016-06-02 10:33:58,870 INFO o.t.o.w.DetailsDocumentWriter:46 Wrote
 details document files
 2016-06-02 10:33:58,870 DEBUG o.t.o.w.DocumentWriterRunner:28 Writing
 BandwidthDocumentWriter
 2016-06-02 11:45:04,633 INFO o.t.o.w.BandwidthDocumentWriter:54 Wrote
 bandwidth document files
 2016-06-02 11:45:04,634 DEBUG o.t.o.w.DocumentWriterRunner:28 Writing
 WeightsDocumentWriter
 2016-06-02 12:19:42,480 INFO o.t.o.w.WeightsDocumentWriter:55 Wrote
 weights document files
 2016-06-02 12:19:42,481 DEBUG o.t.o.w.DocumentWriterRunner:28 Writing
 ClientsDocumentWriter
 2016-06-02 12:23:22,577 INFO o.t.o.w.ClientsDocumentWriter:84 Wrote
 clients document files
 2016-06-02 12:23:22,577 DEBUG o.t.o.w.DocumentWriterRunner:28 Writing
 UptimeDocumentWriter
 2016-06-02 12:39:58,477 INFO o.t.o.w.UptimeDocumentWriter:57 Wrote uptime
 document files
 2016-06-02 12:39:58,477 INFO o.t.o.cron.Main:199 Shutting down.
 2016-06-02 12:39:58,477 DEBUG o.t.o.u.DescriptorSource:204 Writing parse
 histories for recent descriptors...
 2016-06-02 12:39:58,492 INFO o.t.o.cron.Main:202 Wrote parse histories

 karsten at onionoo:/srv/onionoo.thecthulhu.com/onionoo$ java
 -DLOGBASE=/srv/onionoo.thecthulhu.com/onionoo/log-cron/ -Xmx4g -jar
 dist/onionoo-3.1.0.jar --single-run && java
 -DLOGBASE=/srv/onionoo.thecthulhu.com/onionoo/log-cron/ -Xmx4g -jar
 dist/onionoo-3.1.0.jar
 Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
         at java.util.Arrays.copyOf(Arrays.java:2367)
         at
 java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:130)
         at
 java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:114)
         at
 java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:415)
         at java.lang.StringBuilder.append(StringBuilder.java:132)
         at
 org.torproject.onionoo.docs.DocumentStore.writeNodeStatuses(DocumentStore.java:710)
         at
 org.torproject.onionoo.docs.DocumentStore.flushDocumentCache(DocumentStore.java:669)
         at org.torproject.onionoo.cron.Main.shutDown(Main.java:205)
         at org.torproject.onionoo.cron.Main.run(Main.java:121)
         at
 org.torproject.onionoo.cron.Main.runOrScheduleExecutions(Main.java:93)
         at org.torproject.onionoo.cron.Main.main(Main.java:32)

 karsten at onionoo:/srv/onionoo.thecthulhu.com/onionoo$ ls -lh in/archive/
 total 6.9G
 -rw-r--r-- 1 karsten karsten 2.9G May 31 23:40 bridge-
 descriptors-2016-05.tar
 -rw-r--r-- 1 karsten karsten 1.1G May 30 23:19 consensuses-2016-05.tar
 -rw-r--r-- 1 karsten karsten 1.5G May 31 15:57 extra-infos-2016-05.tar
 -rw-r--r-- 1 karsten karsten 1.5G May 31 12:41 server-
 descriptors-2016-05.tar
 }}}

 I didn't really start investigating.  Note that it takes over 24 hours to
 do the processing, so we cannot reproduce this bug as easily.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/19249>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online

More information about the tor-bugs mailing list