search

zielu / GitToolBox

GitToolBox IntelliJ plugin
GNU General Public License v3.0
604 stars 73 forks source link

[BUG]Too much logging freezes CLion #400

Closed enerjazzer closed 1 year ago

enerjazzer commented 2 years ago

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

zielu commented 2 years ago

Ouch, on it - @enerjazzer which plugin version are you using ?

zielu commented 2 years ago

Please try 211/212.9.3 from EAP channel

enerjazzer commented 2 years ago

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?

zielu commented 2 years ago

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.

enerjazzer commented 2 years ago 
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.

enerjazzer commented 2 years ago

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 java.base@17.0.3/java.io.FileOutputStream.writeBytes(Native Method)
    at java.base@17.0.3/java.io.FileOutputStream.write(FileOutputStream.java:349)
    at java.base@17.0.3/java.io.BufferedOutputStream.write(BufferedOutputStream.java:123)
    at java.base@17.0.3/java.io.PrintStream.write(PrintStream.java:568)
    at java.base@17.0.3/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:234)
    at java.base@17.0.3/sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:313)
    at java.base@17.0.3/sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:318)
    at java.base@17.0.3/sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:160)
    at java.base@17.0.3/java.io.OutputStreamWriter.flush(OutputStreamWriter.java:248)
    at java.logging@17.0.3/java.util.logging.StreamHandler.flush(StreamHandler.java:247)
    at java.logging@17.0.3/java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:96)
    at java.logging@17.0.3/java.util.logging.Logger.log(Logger.java:980)
    at java.logging@17.0.3/java.util.logging.Logger.doLog(Logger.java:1007)
    at java.logging@17.0.3/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 java.base@17.0.3/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 java.base@17.0.3/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base@17.0.3/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base@17.0.3/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base@17.0.3/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base@17.0.3/java.lang.Thread.run(Thread.java:833)
zielu commented 2 years ago

This is perfect - should narrow down root cause accurately

zielu commented 2 years ago

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.

enerjazzer commented 2 years ago

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 java.base@17.0.3/java.io.FileOutputStream.writeBytes(Native Method)
    at java.base@17.0.3/java.io.FileOutputStream.write(FileOutputStream.java:349)
    at java.base@17.0.3/java.io.BufferedOutputStream.write(BufferedOutputStream.java:123)
    at java.base@17.0.3/java.io.PrintStream.write(PrintStream.java:568)
    at java.base@17.0.3/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:234)
    at java.base@17.0.3/sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:313)
    at java.base@17.0.3/sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:318)
    at java.base@17.0.3/sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:160)
    at java.base@17.0.3/java.io.OutputStreamWriter.flush(OutputStreamWriter.java:248)
    at java.logging@17.0.3/java.util.logging.StreamHandler.flush(StreamHandler.java:247)
    at java.logging@17.0.3/java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:96)
    at java.logging@17.0.3/java.util.logging.Logger.log(Logger.java:980)
    at java.logging@17.0.3/java.util.logging.Logger.doLog(Logger.java:1007)
    at java.logging@17.0.3/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 java.base@17.0.3/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base@17.0.3/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base@17.0.3/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base@17.0.3/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base@17.0.3/java.lang.Thread.run(Thread.java:833)
zielu commented 2 years ago

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

zielu commented 2 years ago

212.9.5 is out in EAP channel too