Support ICS files above around 18-25 MB #716
Description
Before moving to ktor large ics files did not seem to be a problem for some users. Now one might experience OutOfMemoryErrors for ICS files above around 18-25 MB.
Maybe the switch to ical4j v4 will already help, otherwise we could look into stream preprocessing in ical4android.
Logs
09-18 17:14:02.226 15457 15457 I icsx5 : Manual sync, ignoring network condition
09-18 17:14:02.236 15457 15497 D WM-SystemJobScheduler: Scheduling work ID 4ff24a30-a282-4805-a6b1-ce931ee5e612Job ID 1588
09-18 17:14:02.243 15457 15497 D WM-GreedyScheduler: Starting work for 4ff24a30-a282-4805-a6b1-ce931ee5e612
09-18 17:14:02.244 15457 15497 D WM-Processor: Processor: processing WorkGenerationalId(workSpecId=4ff24a30-a282-4805-a6b1-ce931ee5e612, generation=0)
09-18 17:14:02.245 15457 15457 D WM-SystemJobService: onStartJob for WorkGenerationalId(workSpecId=4ff24a30-a282-4805-a6b1-ce931ee5e612, generation=0)
09-18 17:14:02.245 15457 15457 D WM-WorkerWrapper: Starting work for at.bitfire.icsdroid.SyncWorker
09-18 17:14:02.248 15457 15497 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
09-18 17:14:02.249 15457 15497 D WM-Processor: Work WorkGenerationalId(workSpecId=4ff24a30-a282-4805-a6b1-ce931ee5e612, generation=0) is already enqueued for processing
09-18 17:14:02.252 15457 15502 D icsx5 : Updating local calendar #7 from subscription
09-18 17:14:02.267 15457 15502 I icsx5 : Synchronizing https://192.168.0.100:5006/Calendar/Outlook_Calendar.ics, forceResync=false
09-18 17:14:02.268 15457 15502 I icsx5 : Fetching remote file https://192.168.0.100:5006/Calendar/Outlook_Calendar.ics
09-18 17:14:02.306 15457 16710 W CustomCertManager: Host name "192.168.0.100" not verified, checking whether certificate is explicitly trusted
09-18 17:14:05.620 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:05.620 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:05.634 15457 15502 I itfire.icsdroi: Alloc young concurrent copying GC freed 963(78KB) AllocSpace objects, 0(0B) LOS objects, 10% free, 210MB/234MB, paused 39us,26us total 13.341ms
09-18 17:14:05.634 15457 15502 I itfire.icsdroi: Forcing collection of SoftReferences for 50MB allocation
09-18 17:14:05.634 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:05.662 15457 15502 I itfire.icsdroi: Alloc concurrent copying GC freed 3552(9451KB) AllocSpace objects, 2(32MB) LOS objects, 12% free, 169MB/193MB, paused 38us,24us total 27.891ms
09-18 17:14:06.109 15457 15502 I itfire.icsdroi: Waiting for a blocking GC Alloc
09-18 17:14:06.129 15457 15502 I itfire.icsdroi: WaitForGcToComplete blocked Alloc on Background for 20.732ms
09-18 17:14:06.129 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.337 15457 15502 I itfire.icsdroi: Waiting for a blocking GC Alloc
09-18 17:14:06.361 15457 15502 I itfire.icsdroi: WaitForGcToComplete blocked Alloc on Background for 23.335ms
09-18 17:14:06.361 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.361 15457 15502 I itfire.icsdroi: Forcing collection of SoftReferences for 32MB allocation
09-18 17:14:06.361 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.390 15457 15502 I itfire.icsdroi: Alloc concurrent copying GC freed 199(34KB) AllocSpace objects, 1(32MB) LOS objects, 10% free, 201MB/225MB, paused 53us,23us total 28.976ms
09-18 17:14:06.390 15457 15466 I itfire.icsdroi: WaitForGcToComplete blocked Background on Alloc for 28.801ms
09-18 17:14:06.412 15457 15502 I itfire.icsdroi: Waiting for a blocking GC Alloc
09-18 17:14:06.426 15457 15502 I itfire.icsdroi: WaitForGcToComplete blocked Alloc on Background for 14.323ms
09-18 17:14:06.426 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.426 15457 15502 I itfire.icsdroi: Forcing collection of SoftReferences for 32MB allocation
09-18 17:14:06.426 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.457 15457 15502 I itfire.icsdroi: Alloc concurrent copying GC freed 144(33KB) AllocSpace objects, 1(32MB) LOS objects, 10% free, 201MB/225MB, paused 39us,123us total 30.352ms
09-18 17:14:06.457 15457 15466 I itfire.icsdroi: WaitForGcToComplete blocked Background on Alloc for 30.624ms
09-18 17:14:06.469 15457 15502 I itfire.icsdroi: Waiting for a blocking GC Alloc
09-18 17:14:06.500 15457 15502 I itfire.icsdroi: WaitForGcToComplete blocked Alloc on Background for 30.958ms
09-18 17:14:06.500 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.500 15457 15502 I itfire.icsdroi: Forcing collection of SoftReferences for 50MB allocation
09-18 17:14:06.500 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.535 15457 15502 I itfire.icsdroi: Alloc concurrent copying GC freed 339(33KB) AllocSpace objects, 1(32MB) LOS objects, 10% free, 201MB/225MB, paused 154us,49us total 34.933ms
09-18 17:14:06.536 15457 15466 I itfire.icsdroi: WaitForGcToComplete blocked Background on Alloc for 34.737ms
09-18 17:14:06.589 15457 15502 I itfire.icsdroi: Waiting for a blocking GC Alloc
09-18 17:14:06.647 15457 15502 I itfire.icsdroi: WaitForGcToComplete blocked Alloc on Background for 57.731ms
09-18 17:14:06.647 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.647 15457 15502 I itfire.icsdroi: Forcing collection of SoftReferences for 50MB allocation
09-18 17:14:06.647 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.698 15457 15502 I itfire.icsdroi: Alloc concurrent copying GC freed 290(33KB) AllocSpace objects, 0(0B) LOS objects, 9% free, 220MB/244MB, paused 128us,25us total 50.455ms
09-18 17:14:06.698 15457 15502 W itfire.icsdroi: Throwing OutOfMemoryError "Failed to allocate a 52908664 byte allocation with 25165824 free bytes and 35MB until OOM, target footprint 255868208, growth limit 268435456" (VmSize 17477052 kB)
09-18 17:14:06.698 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.698 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.711 15457 15502 I itfire.icsdroi: Alloc young concurrent copying GC freed 92(46KB) AllocSpace objects, 0(0B) LOS objects, 9% free, 220MB/244MB, paused 36us,22us total 13.554ms
09-18 17:14:06.712 15457 15502 I itfire.icsdroi: Forcing collection of SoftReferences for 50MB allocation
09-18 17:14:06.712 15457 15502 I itfire.icsdroi: Starting a blocking GC Alloc
09-18 17:14:06.737 15457 15502 I itfire.icsdroi: Alloc concurrent copying GC freed 134(33KB) AllocSpace objects, 0(0B) LOS objects, 9% free, 220MB/244MB, paused 41us,24us total 25.200ms
09-18 17:14:06.737 15457 15502 W itfire.icsdroi: Throwing OutOfMemoryError "Failed to allocate a 52908664 byte allocation with 25165824 free bytes and 35MB until OOM, target footprint 255868176, growth limit 268435456" (VmSize 17477052 kB)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: Work [ id=4ff24a30-a282-4805-a6b1-ce931ee5e612, tags={ at.bitfire.icsdroid.SyncWorker } ] failed because it threw an exception/error
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: java.lang.OutOfMemoryError: Failed to allocate a 52908664 byte allocation with 25165824 free bytes and 35MB until OOM, target footprint 255868176, growth limit 268435456
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at java.lang.StringFactory.newStringFromChars(StringFactory.java:112)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at java.nio.HeapCharBuffer.toString(HeapCharBuffer.java:208)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at java.nio.CharBuffer.toString(CharBuffer.java:1074)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at java.util.regex.Matcher.reset(Matcher.java:1161)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at java.util.regex.Matcher.region(Matcher.java:923)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at java.util.Scanner.findPatternInBuffer(Scanner.java:1027)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at java.util.Scanner.findWithinHorizon(Scanner.java:1702)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at at.bitfire.ical4android.validation.StreamPreprocessor.preprocess(SourceFile:39)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at at.bitfire.ical4android.validation.ICalPreprocessor.preprocessStream(SourceFile:51)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at at.bitfire.ical4android.ICalendar$Companion.fromReader(SourceFile:90)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at at.bitfire.ical4android.Event$Companion.eventsFromReader(SourceFile:120)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at at.bitfire.ical4android.Event$Companion.eventsFromReader$default(SourceFile:116)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at at.bitfire.icsdroid.ProcessEventsTask$processEvents$downloader$1.onSuccess(SourceFile:168)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at at.bitfire.icsdroid.CalendarFetcher.fetchNetwork$icsx5_91_2_4_2_gplayRelease(SourceFile:158)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at at.bitfire.icsdroid.CalendarFetcher$fetchNetwork$1.invokeSuspend(Unknown Source:11)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(SourceFile:34)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at kotlinx.coroutines.DispatchedTask.run(SourceFile:100)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(SourceFile:586)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(SourceFile:829)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(SourceFile:717)
09-18 17:14:06.738 15457 15507 E WM-WorkerWrapper: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(SourceFile:704)
09-18 17:14:06.742 15457 15457 D WM-Processor: Processor 4ff24a30-a282-4805-a6b1-ce931ee5e612 executed; reschedule = false
09-18 17:14:06.742 15457 15457 D WM-SystemJobService: 4ff24a30-a282-4805-a6b1-ce931ee5e612 executed on JobScheduler
09-18 17:14:06.746 15457 15507 D WM-GreedyScheduler: Cancelling work ID 4ff24a30-a282-4805-a6b1-ce931ee5e612
09-18 17:14:06.755 15457 15508 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver disabled
--
Internal ticket: https://bitfire-at.zammad.com/#ticket/zoom/11341
Depends on bitfireAT/synctools#90