GitToolBox
GitToolBox copied to clipboard
zielu
[BUG]Too much logging freezes CLion
I use a lot of repos at the same time for my big project, and now I frequently have CLion freezing on logging, and I need to kill it multiple times a day. Please reduce logging or add an option to control it. For example: java.lang.Thread.run 162100ms java.util.concurrent.ThreadPoolExecutor$Worker.run 162100ms java.util.concurrent.ThreadPoolExecutor.runWorker 162100ms java.util.concurrent.FutureTask.run 162100ms java.util.concurrent.Executors$RunnableAdapter.call 162100ms zielu.a.f.a$$Lambda$2756/0x000000080177fc08.run 162100ms zielu.a.f.a.c 162100ms zielu.gittoolbox.a.l.invoke 162100ms zielu.gittoolbox.a.l.a 162100ms zielu.gittoolbox.B.g.run 162100ms zielu.gittoolbox.B.f.run 162100ms zielu.gittoolbox.a.t.run 162100ms zielu.gittoolbox.a.o.b 162100ms zielu.a.h.a.e.a 162100ms com.codahale.metrics.Timer.timeSupplier 162100ms zielu.a.h.a.e$$Lambda$2709/0x000000080174a270.get 162100ms zielu.a.h.a.e.c 162100ms zielu.gittoolbox.a.t$$Lambda$3680/0x0000000801d1df00.invoke 162100ms zielu.gittoolbox.a.t.b 162100ms zielu.gittoolbox.a.B.a 162100ms zielu.gittoolbox.a.a.d.a 162100ms zielu.a.d.a.a 162100ms com.google.common.cache.LocalCache$LocalLoadingCache.get 162100ms com.google.common.cache.LocalCache.getOrLoad 162100ms com.google.common.cache.LocalCache.get 162100ms com.google.common.cache.LocalCache$Segment.get 162100ms com.google.common.cache.LocalCache$Segment.lockedGetOrLoad 162100ms com.google.common.cache.LocalCache$Segment.loadSync 162100ms com.google.common.cache.LocalCache$LoadingValueReference.loadFuture 162100ms zielu.a.d.b.load 162100ms zielu.gittoolbox.a.a.f.a 162100ms zielu.gittoolbox.a.a.f.a 162100ms zielu.gittoolbox.a.a.d.a 162100ms zielu.gittoolbox.a.a.d.b 162100ms zielu.gittoolbox.a.a.d.b 162100ms zielu.gittoolbox.a.a.g.a 162100ms zielu.gittoolbox.a.a.a.a.a 162100ms zielu.gittoolbox.a.a.a.a.b 162100ms com.intellij.openapi.diagnostic.JulLogger.info 162100ms java.util.logging.Logger.log 162100ms java.util.logging.Logger.doLog 162100ms java.util.logging.Logger.log 162100ms java.util.logging.ConsoleHandler.publish 162100ms java.util.logging.StreamHandler.publish 162100ms
Please try 211/212.9.3 from EAP channel
It still logs a lot of #z.g.blame, #z.g.status, #g.c.GitHandler etc. Did you add any options to disable logging?
Do you still get logs with timing in ms or it's just amount of logs now. Logging should not be the root cause - there was deadlock possible that was eliminated. If you do still get logs with timings please share them.
2022-06-17 02:40:16,906 [15081760] INFO - #z.g.blame - Stored blame: <file>;82ff8f7ccf54365c171c19cfc4236d3d20e5b35e
2022-06-17 02:40:16,906 [15081760] INFO - #z.g.blame - Remove outdated entries: []
2022-06-17 02:40:16,906 [15081760] INFO - #z.g.blame - Remove overflowing entries: [<another file>;5a947d6f48763f0880cb807d38acbfb5a52c42b0]
2022-06-17 02:40:16,906 [15081760] INFO - #z.g.blame - Annotated file://<file>:zielu.gittoolbox.a.d@254ab9e2
I guess this means I have ms. But also the amount of logging should be controlled by options. Apparently IDEA machinery just can't keep up and freezes when there is too much logging. Also, most of that logging like the above is for debugging only, useless for me as a user, but they make idea.log files enormous.
The freeze is still happening with 212.9.3, with the same backtrace mentioning gittoolbox:
Freeze for 125 seconds
IDE KILLED! Sampled time: 115000ms, sampling rate: 100ms, GC time: 209ms (0%), Class loading: 0%, cpu load: 27%
The stack is from the thread that was blocking EDT
com.intellij.diagnostic.Freeze
at [email protected]/java.io.FileOutputStream.writeBytes(Native Method)
at [email protected]/java.io.FileOutputStream.write(FileOutputStream.java:349)
at [email protected]/java.io.BufferedOutputStream.write(BufferedOutputStream.java:123)
at [email protected]/java.io.PrintStream.write(PrintStream.java:568)
at [email protected]/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:234)
at [email protected]/sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:313)
at [email protected]/sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:318)
at [email protected]/sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:160)
at [email protected]/java.io.OutputStreamWriter.flush(OutputStreamWriter.java:248)
at [email protected]/java.util.logging.StreamHandler.flush(StreamHandler.java:247)
at [email protected]/java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:96)
at [email protected]/java.util.logging.Logger.log(Logger.java:980)
at [email protected]/java.util.logging.Logger.doLog(Logger.java:1007)
at [email protected]/java.util.logging.Logger.log(Logger.java:1118)
at com.intellij.openapi.diagnostic.JulLogger.warn(JulLogger.java:67)
at com.intellij.idea.IdeaLogger.warn(IdeaLogger.java:136)
at com.intellij.openapi.diagnostic.Logger.warn(Logger.java:174)
at zielu.gittoolbox.a.a.o.b(SourceFile:49)
at zielu.gittoolbox.a.a.o.a(SourceFile:25)
at zielu.gittoolbox.a.a.o$$Lambda$3679/0x0000000801c1d4b8.get(Unknown Source)
at com.codahale.metrics.Timer.timeSupplier(Timer.java:136)
at zielu.a.h.a.e.a(SourceFile:14)
at zielu.gittoolbox.a.a.o.a(SourceFile:24)
at zielu.gittoolbox.a.a.d.b(SourceFile:70)
at zielu.gittoolbox.a.a.d.a(SourceFile:44)
at zielu.gittoolbox.a.a.d$$Lambda$3677/0x0000000801c176e8.apply(Unknown Source)
at com.github.benmanes.caffeine.cache.LocalCache.lambda$statsAware$2(LocalCache.java:165)
at com.github.benmanes.caffeine.cache.LocalCache$$Lambda$1913/0x0000000801310270.apply(Unknown Source)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.lambda$doComputeIfAbsent$13(BoundedLocalCache.java:2550)
at com.github.benmanes.caffeine.cache.BoundedLocalCache$$Lambda$1914/0x0000000801310fd8.apply(Unknown Source)
at [email protected]/java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1955)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.doComputeIfAbsent(BoundedLocalCache.java:2548)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.computeIfAbsent(BoundedLocalCache.java:2531)
at com.github.benmanes.caffeine.cache.LocalCache.computeIfAbsent(LocalCache.java:110)
at com.github.benmanes.caffeine.cache.LocalManualCache.get(LocalManualCache.java:62)
at zielu.gittoolbox.a.a.d.a(SourceFile:42)
at zielu.gittoolbox.a.K.a(SourceFile:30)
at zielu.gittoolbox.a.s.a(SourceFile:202)
at zielu.gittoolbox.a.s.a(SourceFile:179)
at zielu.gittoolbox.a.t.a(SourceFile:193)
at zielu.gittoolbox.a.t.invoke(SourceFile:193)
at zielu.a.h.a.e.c(SourceFile:10)
at zielu.a.h.a.e$$Lambda$2686/0x000000080174e498.get(Unknown Source)
at com.codahale.metrics.Timer.timeSupplier(Timer.java:136)
at zielu.a.h.a.e.a(SourceFile:10)
at zielu.gittoolbox.a.m.b(SourceFile:36)
at zielu.gittoolbox.a.s.run(SourceFile:193)
at zielu.a.b.d.a(SourceFile:11)
at zielu.a.b.m.a(SourceFile:20)
at zielu.a.b.m.invoke(SourceFile:18)
at zielu.a.k.d.a(SourceFile:23)
at zielu.a.b.j.run(SourceFile:18)
at zielu.gittoolbox.a.i.run(SourceFile:49)
at zielu.a.i.g.run(SourceFile:130)
at zielu.a.c.a.a(SourceFile:64)
at zielu.a.c.a$$Lambda$3673/0x0000000801c130c8.run(Unknown Source)
at zielu.gittoolbox.a.k.a(SourceFile:33)
at zielu.gittoolbox.a.k.invoke(SourceFile:32)
at zielu.gittoolbox.b.a(SourceFile:77)
at zielu.gittoolbox.b$$Lambda$3674/0x0000000801c13588.run(Unknown Source)
at zielu.a.b.i.run(SourceFile:12)
at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at [email protected]/java.lang.Thread.run(Thread.java:833)
212.9.4 should be up shortly in EAP channel, I think I found the issue causing freezing, but underneath it lies another issue - it looks like inline blame is failing to run blame command and writing out error log is what was causing the freeze (that error message must be quite big indeed). Blame error will be logged in warn level (with reduced info now), if you could take a look there it might say something useful about why command is failing in the first place.
This is for 212.9.4 :(
Freeze for 182 seconds
IDE KILLED! Sampled time: 169500ms, sampling rate: 100ms, GC time: 198ms (0%), Class loading: 0%, cpu load: 1%
The stack is from the thread that was blocking EDT
com.intellij.diagnostic.Freeze
at [email protected]/java.io.FileOutputStream.writeBytes(Native Method)
at [email protected]/java.io.FileOutputStream.write(FileOutputStream.java:349)
at [email protected]/java.io.BufferedOutputStream.write(BufferedOutputStream.java:123)
at [email protected]/java.io.PrintStream.write(PrintStream.java:568)
at [email protected]/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:234)
at [email protected]/sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:313)
at [email protected]/sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:318)
at [email protected]/sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:160)
at [email protected]/java.io.OutputStreamWriter.flush(OutputStreamWriter.java:248)
at [email protected]/java.util.logging.StreamHandler.flush(StreamHandler.java:247)
at [email protected]/java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:96)
at [email protected]/java.util.logging.Logger.log(Logger.java:980)
at [email protected]/java.util.logging.Logger.doLog(Logger.java:1007)
at [email protected]/java.util.logging.Logger.log(Logger.java:1118)
at com.intellij.openapi.diagnostic.JulLogger.warn(JulLogger.java:67)
at com.intellij.idea.IdeaLogger.warn(IdeaLogger.java:136)
at com.intellij.openapi.diagnostic.Logger.warn(Logger.java:174)
at zielu.gittoolbox.a.a.o.b(SourceFile:54)
at zielu.gittoolbox.a.a.o.a(SourceFile:26)
at zielu.gittoolbox.a.a.o$$Lambda$3646/0x0000000801bc71c0.get(Unknown Source)
at com.codahale.metrics.Timer.timeSupplier(Timer.java:136)
at zielu.a.h.a.e.a(SourceFile:14)
at zielu.gittoolbox.a.a.o.a(SourceFile:25)
at zielu.gittoolbox.a.a.d.b(SourceFile:73)
at zielu.gittoolbox.a.a.d.a(SourceFile:44)
at zielu.gittoolbox.a.L.a(SourceFile:30)
at zielu.gittoolbox.a.s.a(SourceFile:212)
at zielu.gittoolbox.a.s.a(SourceFile:188)
at zielu.gittoolbox.a.t.a(SourceFile:203)
at zielu.gittoolbox.a.t.invoke(SourceFile:203)
at zielu.a.h.a.e.c(SourceFile:10)
at zielu.a.h.a.e$$Lambda$2489/0x00000008015639d0.get(Unknown Source)
at com.codahale.metrics.Timer.timeSupplier(Timer.java:136)
at zielu.a.h.a.e.a(SourceFile:10)
at zielu.gittoolbox.a.l.b(SourceFile:36)
at zielu.gittoolbox.a.s.run(SourceFile:203)
at zielu.a.b.f.a(SourceFile:11)
at zielu.a.b.o.a(SourceFile:21)
at zielu.a.b.o.invoke(SourceFile:18)
at zielu.a.k.d.a(SourceFile:23)
at zielu.a.b.l.run(SourceFile:18)
at zielu.gittoolbox.a.i.run(SourceFile:52)
at zielu.a.i.f.run(SourceFile:129)
at zielu.a.b.f.a(SourceFile:11)
at zielu.a.b.o.a(SourceFile:21)
at zielu.a.b.o.invoke(SourceFile:18)
at zielu.a.k.d.a(SourceFile:23)
at zielu.a.b.l.run(SourceFile:18)
at zielu.a.c.f.run(SourceFile:70)
at zielu.a.b.f.a(SourceFile:11)
at zielu.a.b.o.a(SourceFile:21)
at zielu.a.b.o.invoke(SourceFile:18)
at zielu.a.k.d.a(SourceFile:23)
at zielu.a.b.l.run(SourceFile:18)
at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at [email protected]/java.lang.Thread.run(Thread.java:833)
Eeh, I'll continue the investigation - there must be some place that switches to UI thread...
I created dev build that truncates more logs - so far I don't see a reason how this all could be blocking the UI thread. It can be installed like this gittoolbox-212.9.5-SNAPSHOT.zip