Azure / DotNetty

DotNetty project – a port of netty, event-driven asynchronous network application framework
Other
4.09k stars 977 forks source link

ResourceLeakDetector sometimes report current using buffer as leak in 0.4.7 #308

Closed yyjdelete closed 6 years ago

yyjdelete commented 6 years ago

Seems it works well with 0.4.6

@StormHub A lot of things changed after 0.4.6, so don't what make the difference. Is an extra GC.SuppressFinalize(GCNotice) is needed? (But not see in 0.4.6 either)

Test Code ```cs using DotNetty.Buffers; using DotNetty.Common; using Microsoft.Extensions.Logging; using System; namespace ConsoleApp1 { class Program { static void Main(string[] args) { DotNetty.Common.Internal.Logging.InternalLoggerFactory.DefaultFactory.AddConsole(); ResourceLeakDetector.Level = ResourceLeakDetector.DetectionLevel.Paranoid; var logger = DotNetty.Common.Internal.Logging.InternalLoggerFactory.DefaultFactory.CreateLogger(typeof(Program)); var alloc = ByteBufferUtil.DefaultAllocator; for (var i = 0; i < 2; ++i) { logger.LogInformation("start buf" + i); var buf = alloc.Buffer(); GC.Collect(GC.MaxGeneration, GCCollectionMode.Forced, true); for (var j = 0; j < 4; ++j) { buf.WriteByte(i); buf.WriteByte(j); } logger.LogInformation(ByteBufferUtil.HexDump(buf)); buf.Release(); logger.LogInformation("end buf" + i); } logger.LogInformation("The End"); Console.ReadLine(); } } } ```
caozhiyuan commented 6 years ago

now when gc , gcnotice will be collect but buffer not write.

add a reference to gcnotice may can slove this problem @yyjdelete @StormHub .

https://github.com/caozhiyuan/DotNetty/blob/dev/src/DotNetty.Common/ResourceLeakDetector.cs#L81

yyjdelete commented 6 years ago

@caozhiyuan I make another patch, tested with DetectionLevel.Paranoid and Echo as you described in gitter, can you check if this works for you? https://github.com/yyjdelete/DotNetty/commit/a67d13e86cd02f5fa74ea9cef19b4f33f5cfbc5f

@StormHub Should the key/value in gcNotificationMap be removed when Rearm is called? See CloseFinal.

StormHub commented 6 years ago

@yyjdelete No need to remove it for Rearm because it means that there is already an entry there. I still don't know what was the problem here.

caozhiyuan commented 6 years ago

@StormHub run this ` static void Main(string[] args) { DotNetty.Common.Internal.Logging.InternalLoggerFactory.DefaultFactory.AddConsole(); ResourceLeakDetector.Level = ResourceLeakDetector.DetectionLevel.Paranoid;

        var logger = DotNetty.Common.Internal.Logging.InternalLoggerFactory.DefaultFactory.CreateLogger(typeof(Program));
        var alloc = ByteBufferUtil.DefaultAllocator;
        for (var i = 0; i < 2; ++i)
        {
            logger.LogInformation("start buf" + i);
            var buf = alloc.Buffer();
            GC.Collect(GC.MaxGeneration, GCCollectionMode.Forced, true);
            for (var j = 0; j < 4; ++j)
            {
                buf.WriteByte(i);
                buf.WriteByte(j);
            }
            logger.LogInformation(ByteBufferUtil.HexDump(buf));
            buf.Release();
            logger.LogInformation("end buf" + i);
        }
        logger.LogInformation("The End");

        Console.ReadLine();
    }

`

yyjdelete commented 6 years ago

@StormHub

  1. Close not call GC.SuppressFinalize(GCNotice) and no check in CloseFinal to make sure object.ReferenceEquals(GCNotice.leak, this) before remove, so finalizer may be called after this buffer is added again and remove the new GCNotice. And the same thing for Rearm. See the missing assert in the second commit to tracking this.
  2. In very rare case, GCNotice will be collect right after Remove in Close with the modified CloseFinal.

See https://github.com/Azure/DotNetty/compare/dev...yyjdelete:test-308

@caozhiyuan Can you check if it works for you? If it works, I will create an PR later.

StormHub commented 6 years ago

Let have a look at first.

StormHub commented 6 years ago

@yyjdelete I still cannot reproduce the problem here.

caozhiyuan commented 6 years ago

set ResourceLeakDetector.Level = ResourceLeakDetector.DetectionLevel.Paranoid; and i'm use netcoreapp2.0

StormHub commented 6 years ago

@caozhiyuan it is on Paranoid all the time and nothing unusual happened.

caozhiyuan commented 6 years ago

send you code , i have a look

yyjdelete commented 6 years ago

You can try increase the loop of i to 3 or more, 2 also not works for me.

StormHub commented 6 years ago

//When you doing the test, you might want to wait for finalizer thread to finish GC.Collect(GC.MaxGeneration, GCCollectionMode.Forced, true); GC.WaitForPendingFinalizers(); // Empty finalizer queue

caozhiyuan commented 6 years ago

now i debug code add log, find buffer still in channeloutboundbuffer and not release , but gc tigger gcnotice finalize it report resource leak, so when buffer sent and release , this.Leak.Close(this.trackedByteBuf) return false

caozhiyuan commented 6 years ago

it may be no object ref gcnotice , and it can be gc finalized before buffer release and set null ?

caozhiyuan commented 6 years ago

i trace buffer when it reuse set a id to it

yyjdelete commented 6 years ago
``` info: Telnet.Client.Program[0] start buf0 info: DotNetty.Common.ResourceLeakDetector[0] Track with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591 info: DotNetty.Common.ResourceLeakDetector[0] Create GCNotice@41962596 with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591, Leak@42119052 info: Telnet.Client.Program[0] 00000001 info: DotNetty.Common.ResourceLeakDetector[0] Close with PooledUnsafeDirectByteBuffer(freed)@19575591 info: DotNetty.Common.ResourceLeakDetector[0] Close->GCNotice@41962596, NewLeak@42119052 vs OldLeak@42119052 info: DotNetty.Common.ResourceLeakDetector[0] Close->true info: Telnet.Client.Program[0] end buf0 info: Telnet.Client.Program[0] start buf1 info: DotNetty.Common.ResourceLeakDetector[0] Track with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591 info: DotNetty.Common.ResourceLeakDetector[0] Create GCNotice@56200037 with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591, Leak@36038289 info: DotNetty.Common.ResourceLeakDetector[0] Finalize with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591, GCNotice@41962596 info: DotNetty.Common.ResourceLeakDetector[0] CloseFinal with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591 info: DotNetty.Common.ResourceLeakDetector[0] CloseFinal->GCNotice@56200037, NewLeak @36038289 vs OldLeak@42119052 info: DotNetty.Common.ResourceLeakDetector[0] CloseFinal->false warn: DotNetty.Common.ResourceLeakDetector[0] System.Diagnostics.Debug+DebugAssertException: CloseFinal->false at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) at System.Environment.get_StackTrace() at System.Diagnostics.Debug.Assert(Boolean condition, String message, String detailMessage) at System.Diagnostics.Debug.Assert(Boolean condition, String message) at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.CloseFinal(Object trackedObject) in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 291 at DotNetty.Common.ResourceLeakDetector.GCNotice.Finalize() in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 446 at System.Diagnostics.Debug.WindowsDebugLogger.ShowAssertDialog(String stackTrace, String message, String detailMessage) at System.Diagnostics.Debug.Assert(Boolean condition, String message, String detailMessage) at System.Diagnostics.Debug.Assert(Boolean condition, String message) at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.CloseFinal(Object trackedObject) in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 291 info: Telnet.Client.Program[0] 01000101 info: DotNetty.Common.ResourceLeakDetector[0] Close with PooledUnsafeDirectByteBuffer(freed)@19575591 info: DotNetty.Common.ResourceLeakDetector[0] Close->false warn: DotNetty.Common.ResourceLeakDetector[0] System.Diagnostics.Debug+DebugAssertException: Close->false at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) at System.Environment.get_StackTrace() at System.Diagnostics.Debug.Assert(Boolean condition, String message, String detailMessage) at System.Diagnostics.Debug.Assert(Boolean condition, String message) at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Close(Object trackedObject) in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 262 at DotNetty.Buffers.SimpleLeakAwareByteBuffer.CloseLeak() in F:\__cur\DotNetty\src\DotNetty.Buffers\SimpleLeakAwareByteBuffer.cs:line 75 at DotNetty.Buffers.SimpleLeakAwareByteBuffer.Release() in F:\__cur\DotNetty\src\DotNetty.Buffers\SimpleLeakAwareByteBuffer.cs:line 54 at DotNetty.Buffers.AdvancedLeakAwareByteBuffer.Release() in F:\__cur\DotNetty\src\DotNetty.Buffers\AdvancedLeakAwareByteBuffer.cs:line 789 at Telnet.Client.Program.Main(String[] args) in F:\__cur\DotNetty\examples\Telnet.Client\Program.cs:line 109 at System.Diagnostics.Debug.WindowsDebugLogger.ShowAssertDialog(String stackTrace, String message, String detailMessage) at System.Diagnostics.Debug.Assert(Boolean condition, String message, String detailMessage) at System.Diagnostics.Debug.Assert(Boolean condition, String message) at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Close(Object trackedObject) in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 262 info: Telnet.Client.Program[0] end buf1 info: Telnet.Client.Program[0] start buf2 info: DotNetty.Common.ResourceLeakDetector[0] Track with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591 info: DotNetty.Common.ResourceLeakDetector[0] Create GCNotice@55909147 with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591, Leak@33420276 info: DotNetty.Common.ResourceLeakDetector[0] Finalize with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591, GCNotice@56200037 info: DotNetty.Common.ResourceLeakDetector[0] CloseFinal with PooledUnsafeDirectByteBuffer(ridx: 0, widx: 0, cap: 256)@19575591 info: DotNetty.Common.ResourceLeakDetector[0] CloseFinal->GCNotice@55909147, NewLeak @33420276 vs OldLeak@36038289 fail: DotNetty.Common.ResourceLeakDetector[0] LEAK: IByteBuffer.Release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information. Recent access records: #1: at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) at System.Environment.get_StackTrace() at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Record0(Object hint) in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 209 at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Record() in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 200 at DotNetty.Buffers.AdvancedLeakAwareByteBuffer.Release() in F:\__cur\DotNetty\src\DotNetty.Buffers\AdvancedLeakAwareByteBuffer.cs:line 788 at Telnet.Client.Program.Main(String[] args) in F:\__cur\DotNetty\examples\Telnet.Client\Program.cs:line 109 #2: at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) at System.Environment.get_StackTrace() at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Record0(Object hint) in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 209 at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Record() in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 200 at DotNetty.Buffers.AdvancedLeakAwareByteBuffer.RecordLeakNonRefCountingOperation(IResourceLeakTracker leak) in F:\__cur\DotNetty\src\DotNetty.Buffers\AdvancedLeakAwareByteBuffer.cs:line 47 at DotNetty.Buffers.AdvancedLeakAwareByteBuffer.GetByte(Int32 index) in F:\__cur\DotNetty\src\DotNetty.Buffers\AdvancedLeakAwareByteBuffer.cs:line 107 at DotNetty.Buffers.ByteBufferUtil.HexUtil.DoHexDump(IByteBuffer buffer, Int32 fromIndex, Int32 length) in F:\__cur\DotNetty\src\DotNetty.Buffers\ByteBufferUtil.cs:line 486 at DotNetty.Buffers.ByteBufferUtil.HexDump(IByteBuffer buffer, Int32 fromIndex, Int32 length) in F:\__cur\DotNetty\src\DotNetty.Buffers\ByteBufferUtil.cs:line 54 at DotNetty.Buffers.ByteBufferUtil.HexDump(IByteBuffer buffer) in F:\__cur\DotNetty\src\DotNetty.Buffers\ByteBufferUtil.cs:line 48 at Telnet.Client.Program.Main(String[] args) in F:\__cur\DotNetty\examples\Telnet.Client\Program.cs:line 108 #3: at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) at System.Environment.get_StackTrace() at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Record0(Object hint) in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 209 at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Record() in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 200 at DotNetty.Buffers.AdvancedLeakAwareByteBuffer.RecordLeakNonRefCountingOperation(IResourceLeakTracker leak) in F:\__cur\DotNetty\src\DotNetty.Buffers\AdvancedLeakAwareByteBuffer.cs:line 47 at DotNetty.Buffers.AdvancedLeakAwareByteBuffer.WriteByte(Int32 value) in F:\__cur\DotNetty\src\DotNetty.Buffers\AdvancedLeakAwareByteBuffer.cs:line 425 at Telnet.Client.Program.Main(String[] args) in F:\__cur\DotNetty\examples\Telnet.Client\Program.cs:line 106 #4: at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) at System.Environment.get_StackTrace() at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Record0(Object hint) in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 209 at DotNetty.Common.ResourceLeakDetector.DefaultResourceLeak.Record() in F:\__cur\DotNetty\src\DotNetty.Common\ResourceLeakDetector.cs:line 200 at DotNetty.Buffers.AdvancedLeakAwareByteBuffer.RecordLeakNonRefCountingOperation(IResourceLeakTracker leak) in F:\__cur\DotNetty\src\DotNetty.Buffers\AdvancedLeakAwareByteBuffer.cs:line 47 at DotNetty.Buffers.AdvancedLeakAwareByteBuffer.WriteByte(Int32 value) in F:\__cur\DotNetty\src\DotNetty.Buffers\AdvancedLeakAwareByteBuffer.cs:line 425 at Telnet.Client.Program.Main(String[] args) in F:\__cur\DotNetty\examples\Telnet.Client\Program.cs:line 105 : 3 leak records were discarded because they were duplicates : 3 leak records were discarded because the leak record count is targeted to 4. Use system property io.netty.leakDetection.targetRecords to increase the limit. ```
StormHub commented 6 years ago

OK I think I know what happened here. The cached byte buffer gets reused before finalizer kicks in to remove the previous GCNotice entry first. When finalizer starts, it treats the current tracking records as leak for previously released byte buffer. The ConditionalWeakTable is keyed by byte buffer, the object.Equal returns true for reused byte buffer.

I have to look at how Netty does avoid this kind of situation before I come up with some fix.

BTW: I think #325 is caused by the same issue.

StormHub commented 6 years ago

@yyjdelete @caozhiyuan this worked, I need to give it a bit more thoughts

//DefaultResourceLeak class

        public bool Close(object trackedObject)
        {
            if (this.owner.gcNotificationMap.TryGetValue(trackedObject, out GCNotice notice))
            {
                GC.SuppressFinalize(notice);
                Debug.Assert(this.owner.gcNotificationMap.Remove(trackedObject));
                Interlocked.Exchange(ref this.head, null);
                return true;
            }

            return false;
        }
nayato commented 6 years ago

fixed with #347