Handle leak in jsonServiceClient?

Clients
1

The latest jsonServiceClient (4.0.54) is leaving handles open after every synchronous GET request (and possibly POSTS).

We were calling it as a load test using client.Get('url/whatever') and ignoring the result.

My guess is that it’s something like the stream for the result, if unread, remains held open and slowly grinds the machine to a halt. We didn’t follow it up further after wasting a full day assuming it was elsewhere in our code :confused:

Running a loop of 10,000 fetches slows our tests down significantly, despite disposing of the client instance.
This doesn’t happen with the Async get call.

2

I’ve previously left a comment on your StackOverflow question. We’re disposing both Request streams and Responses unless the response is a HttpWebResponse or Stream which is the call-sites responsibility to Dispose. If you’re calling an API that returns either one of these Response Types you must dispose them yourself.

Can you please provide the exact code you used that demonstrates the leak?

1 Like
3

I’ve added a regression test trying to repro the leak from the limited info provided in this commit.

First using a Typed Request DTO:

[Test]
public void Run_GET_dto_in_loop()
{
    var client = new JsonServiceClient(Config.ListeningOn);

    client.Get(new LeakRequest { Name = "warmup" });

    var sw = Stopwatch.StartNew();
    var elapsedTicks = new List<double> { sw.ElapsedMilliseconds };

    for (int i = 0; i < 10001; i++)
    {
        var response = client.Get(new LeakRequest { Name = "request" + i });
        Assert.That(response.Name, Is.EqualTo("request" + i));
        elapsedTicks.Add(sw.ElapsedTicks);
    }

    for (int i = 0; i < 10001; i += 1000)
    {
        "Elapsed Time: {0} ticks for Request at: #{1}".Print(
            elapsedTicks[i + 1] - elapsedTicks[i], i);
    }
}

Which outputs:

Elapsed Time: 15413 ticks for Request at: #0
Elapsed Time: 924 ticks for Request at: #1000
Elapsed Time: 845 ticks for Request at: #2000
Elapsed Time: 916 ticks for Request at: #3000
Elapsed Time: 875 ticks for Request at: #4000
Elapsed Time: 995 ticks for Request at: #5000
Elapsed Time: 967 ticks for Request at: #6000
Elapsed Time: 1022 ticks for Request at: #7000
Elapsed Time: 1125 ticks for Request at: #8000
Elapsed Time: 917 ticks for Request at: #9000
Elapsed Time: 862 ticks for Request at: #10000

And a request testing a url request:

[Test]
public void Run_GET_url_in_loop()
{
    var client = new JsonServiceClient(Config.ListeningOn);

    client.Get(new LeakRequest { Name = "warmup" });

    var sw = Stopwatch.StartNew();
    var elapsedTicks = new List<double> { sw.ElapsedMilliseconds };

    for (int i = 0; i < 10001; i++)
    {
        var response = client.Get<LeakRequest>("/leak/request" + i);
        Assert.That(response.Name, Is.EqualTo("request" + i));
        elapsedTicks.Add(sw.ElapsedTicks);
    }

    for (int i = 0; i < 10001; i += 1000)
    {
        "Elapsed Time: {0} ticks for Request at: #{1}".Print(
            elapsedTicks[i + 1] - elapsedTicks[i], i);
    }
}

Which outputs similar results:

Elapsed Time: 19873 ticks for Request at: #0
Elapsed Time: 1146 ticks for Request at: #1000
Elapsed Time: 933 ticks for Request at: #2000
Elapsed Time: 977 ticks for Request at: #3000
Elapsed Time: 807 ticks for Request at: #4000
Elapsed Time: 1054 ticks for Request at: #5000
Elapsed Time: 1075 ticks for Request at: #6000
Elapsed Time: 1058 ticks for Request at: #7000
Elapsed Time: 1068 ticks for Request at: #8000
Elapsed Time: 931 ticks for Request at: #9000
Elapsed Time: 785 ticks for Request at: #10000

None of these load tests show that synchronous GET’s are getting slower. Please provide a stand-alone repro of the test you used that shows that there is a memory leak.

4

Hi Mythz,
The issue is in the returned HttpWebResponse object on the non-generic Get method, which is not in your tests.
As you can see in the comparisons below, the second is leaking open handles to streams, but if the streams is forcibly closed (third example) the problem is gone.
I’m not sure if this is a bug or a ‘by design’ where you assume anyone using the non-generic GET call will always read and close the stream manually. Even if the issue is by design, should disposing of the client also release the associated HttpWebResponse objects? Who is holding them all open?

var x = client.Get<string>($"/hello/{myctr}");

Total: 1623ms, Average: msec: 1.623, Response times average: 7.30
Total: 459ms, Average: msec: 0.459, Response times average: 5.185
Total: 485ms, Average: msec: 0.485, Response times average: 5.512
Total: 475ms, Average: msec: 0.475, Response times average: 5.401
Total: 448ms, Average: msec: 0.448, Response times average: 5.17
Total: 406ms, Average: msec: 0.406, Response times average: 4.706
Total: 409ms, Average: msec: 0.409, Response times average: 4.675
Total: 403ms, Average: msec: 0.403, Response times average: 4.636
Total: 410ms, Average: msec: 0.41, Response times average: 4.711
Total: 404ms, Average: msec: 0.404, Response times average: 4.63
Total: 390ms, Average: msec: 0.39, Response times average: 4.422
Total: 391ms, Average: msec: 0.391, Response times average: 4.378
Total: 405ms, Average: msec: 0.405, Response times average: 4.533
Total: 409ms, Average: msec: 0.409, Response times average: 4.56
Total: 399ms, Average: msec: 0.399, Response times average: 4.4
Total: 385ms, Average: msec: 0.385, Response times average: 4.26
Total: 391ms, Average: msec: 0.391, Response times average: 4.323
Total: 397ms, Average: msec: 0.397, Response times average: 4.424
Total: 410ms, Average: msec: 0.41, Response times average: 4.705
Total: 407ms, Average: msec: 0.407, Response times average: 4.67
Total: 401ms, Average: msec: 0.401, Response times average: 4.566
Total: 398ms, Average: msec: 0.398, Response times average: 4.535
Total: 397ms, Average: msec: 0.397, Response times average: 4.555
Total: 406ms, Average: msec: 0.406, Response times average: 4.642

var x = client.Get($"/hello/{myctr}");

Total: 1347ms, Average: msec: 1.347, Response times average: 15.712
Total: 569ms, Average: msec: 0.569, Response times average: 6.593
Total: 521ms, Average: msec: 0.521, Response times average: 5.927
Total: 519ms, Average: msec: 0.519, Response times average: 5.903
Total: 547ms, Average: msec: 0.547, Response times average: 6.385
Total: 665ms, Average: msec: 0.665, Response times average: 7.726
Total: 748ms, Average: msec: 0.748, Response times average: 8.78
Total: 878ms, Average: msec: 0.878, Response times average: 10.481
Total: 1034ms, Average: msec: 1.034, Response times average: 12.676
Total: 1125ms, Average: msec: 1.125, Response times average: 13.771
Total: 1243ms, Average: msec: 1.243, Response times average: 15.28
Total: 1363ms, Average: msec: 1.363, Response times average: 16.269
Total: 1520ms, Average: msec: 1.52, Response times average: 18.139
Total: 1598ms, Average: msec: 1.598, Response times average: 19.01
Total: 1669ms, Average: msec: 1.669, Response times average: 20.094
Total: 1804ms, Average: msec: 1.804, Response times average: 21.617
Total: 1938ms, Average: msec: 1.938, Response times average: 23.273
Total: 2009ms, Average: msec: 2.009, Response times average: 24.741
Total: 2240ms, Average: msec: 2.24, Response times average: 27.682
Total: 2292ms, Average: msec: 2.292, Response times average: 28.815
Total: 2451ms, Average: msec: 2.451, Response times average: 31.967
Total: 2632ms, Average: msec: 2.632, Response times average: 35.37
Total: 2807ms, Average: msec: 2.807, Response times average: 40.632
Total: 2788ms, Average: msec: 2.788, Response times average: 42.669
Total: 2909ms, Average: msec: 2.909, Response times average: 51.864

var x = client.Get($"/hello/{myctr}");
x.GetResponseStream().Close();

Total: 1719ms, Average: msec: 1.719, Response times average: 8.566
Total: 445ms, Average: msec: 0.445, Response times average: 5.103
Total: 475ms, Average: msec: 0.475, Response times average: 5.501
Total: 489ms, Average: msec: 0.489, Response times average: 5.763
Total: 452ms, Average: msec: 0.452, Response times average: 5.473
Total: 433ms, Average: msec: 0.433, Response times average: 5.249
Total: 466ms, Average: msec: 0.466, Response times average: 5.676
Total: 408ms, Average: msec: 0.408, Response times average: 4.9
Total: 411ms, Average: msec: 0.411, Response times average: 4.965
Total: 418ms, Average: msec: 0.418, Response times average: 4.984
Total: 420ms, Average: msec: 0.42, Response times average: 5.046
Total: 417ms, Average: msec: 0.417, Response times average: 5.033
Total: 407ms, Average: msec: 0.407, Response times average: 4.734
Total: 416ms, Average: msec: 0.416, Response times average: 4.796
Total: 415ms, Average: msec: 0.415, Response times average: 4.775
Total: 404ms, Average: msec: 0.404, Response times average: 4.635
Total: 413ms, Average: msec: 0.413, Response times average: 4.769
Total: 412ms, Average: msec: 0.412, Response times average: 4.724
Total: 414ms, Average: msec: 0.414, Response times average: 4.79
Total: 406ms, Average: msec: 0.406, Response times average: 4.843
Total: 409ms, Average: msec: 0.409, Response times average: 4.92
Total: 413ms, Average: msec: 0.413, Response times average: 4.998
Total: 408ms, Average: msec: 0.408, Response times average: 4.917
Total: 409ms, Average: msec: 0.409, Response times average: 4.93
Total: 404ms, Average: msec: 0.404, Response times average: 4.858
5

I’ve tried to make it clear in the docs, my initial comment as well as the StackOverflow comments of the original question that if you’re calling an API that returns either a HttpWebResponse or Stream you must dispose of the response yourself. The client can’t dispose of it before it returns the response because then you wont be able to access it, therefore you must dispose it after you’ve finished using it. .NET’s WebRequest can’t free the resources around the HTTP connection unless it’s been indicated that the response is no longer needed and can be discarded by either Disposing or Closing the HttpWebResponse.

To make sure the response is properly disposed of you should always call any API that returns either a HttpWebResponse or Stream in a using{} statement as shown in the docs examples.

If you remove the var type inference from your example code you will see that the response that the API you’re calling is a HttpWebResponse, in which case it needs to properly disposed of in a using statement, e.g:

using (HttpWebResponse x = client.Get("/hello/myctr")) {}

If you dispose of it properly as above you should no longer have any issues.

1 Like
6

I’ve added an example calling an API that returns a HttpWebResponse in this commit.

Whilst there’s no leak if you call it within a using statement:

[Test]
public void Run_GET_url_HttpWebResponse_in_loop()
{
    var client = new JsonServiceClient(Config.ListeningOn);

    client.Get(new LeakRequest { Name = "warmup" });

    var sw = Stopwatch.StartNew();
    var elapsedTicks = new List<double> { sw.ElapsedMilliseconds };

    for (int i = 0; i < 10001; i++)
    {
        using (HttpWebResponse response = client.Get("/leak/request" + i)) {}
        elapsedTicks.Add(sw.ElapsedTicks);
    }

    for (int i = 0; i < 10001; i += 1000)
    {
        "Elapsed Time: {0} ticks for Request at: #{1}".Print(
            elapsedTicks[i + 1] - elapsedTicks[i], i);
    }
}

Which returns average fast times that don’t increase:

Elapsed Time: 8900 ticks for Request at: #0
Elapsed Time: 938 ticks for Request at: #1000
Elapsed Time: 919 ticks for Request at: #2000
Elapsed Time: 1118 ticks for Request at: #3000
Elapsed Time: 880 ticks for Request at: #4000
Elapsed Time: 924 ticks for Request at: #5000
Elapsed Time: 751 ticks for Request at: #6000
Elapsed Time: 832 ticks for Request at: #7000
Elapsed Time: 1128 ticks for Request at: #8000
Elapsed Time: 718 ticks for Request at: #9000
Elapsed Time: 845 ticks for Request at: #10000

I previously reported that explicitly the HttpWebResponse was 2x faster, e.g:

using (HttpWebResponse response = client.Get("/leak/request" + i)) {
    response.Close();
}

But upon going back to research the perf differences I couldn’t replicate the results, so there must’ve been something up with my laptop during the previous test run as calling response.Close() within using(response){} isn’t showing any performance improvements anymore.

7

That’s great, thanks.
I would point out that for users not wanting access to the raw response, or in fact any response at all, it’s natural to call the none-generic Get function. As such I think it’s worth adding to the documentation a note that you must dispose of the return value, and not simply the client.
You mention that you can’t dispose of the response as the user would then be unable to use it, which is obvious, but what was less obvious to me is why the response is never disposed despite going out of scope. The native HttpWebResponse is documented as requiring disposal, but in this test the problem is that the GC doesn’t close the stream despite the system running out of steam. Forcing a GC between iterations resolves it, but it’s obviously better to close the stream explicitly.

Is it wise to have a function that returns an opened stream as the default of many signatures when called? Might it be safer to force the user to open the stream if that’s what they want, or suggest they specify Get<HttpWebResponse> as the return type if that’s what they want? Only methods with ‘Stream’ on the end of their name generally require closing.
Just suggesting this to help avoid other people hitting the same unexpected issue.

8

You can already explicitly call Get<HttpWebResponse>() or Get<Stream>() to access the HttpWebResponse or Stream.

But still when how the response should be converted is unknown, the most appropriate response is still to return the underlying HTTP Response since it offers the most flexible API with the ability to access both response stream and HTTP response headers, i.e. the same as what .NET’s WebRequest returns when you call it directly, i.e:

WebRequest webReq = WebRequest.Create(requestUri);
HttpWebResponse webRes = (HttpWebResponse)webReq.GetResponse();

Changing the API name would be a breaking change so we wont do that, but even if we could I still think this is the most appropriate name for it as the only alternative I can think of that would make sense is client.GetResponse() to match the same API name on WebRequest but if we did that then we’d also need to change all the equivalent API’s for the different HTTP Methods, e.g. client.HeadResponse(), client.PostResponse(), client.DeleteResponse(), etc which would range from awkward to misleading. So even if we could rename them, I don’t think there’s a better name and the API’s are still useful when you want to the most flexible access to the HTTP Response so I don’t want to Obsolete them either. The places where we show it’s usage, we also show that they need to be disposed.

Since they’re specific to WebRequest implementations these API’s aren’t available on IServiceClient so they’re only available on the concrete clients inheriting from ServiceClientBase which limits their usage.

If you just want to call the url but don’t care about the response I recommend instead using the HTTP Utils instead which are still nice and terse and don’t require disposing the response, e.g:

string str = requestUri.GetStringFromUrl();
byte[] bytes = requestUri.GetBytesFromUrl();