Cloning CdsServiceClient can take a while in latest release

[mathiasbl]

In the latest release with MSAL cloning the client can take a long time in a multithreaded application.

Here's a gist to reproduce. It's a simple, non-optimalized, example
https://gist.github.com/mathiasbl/92863ad85074975e5f2d6bb8062e3eb3

Run this example with the latest release vs the previous one and you should see considerable difference in time.

[MattB-msft]

Could you share a bit more of what your seeing?
we have similar tests which do not show substantial difference between ADAL.net and MSAL use.
there is a progressive increase in time based on the way in which your code is written due to the .net garbage collector work and the nature of the Stopwatch component.

We are wondering if that's the difference. however we are curious what your numbers look like.

thanks
MattB

[mathiasbl]

I have an Azure Service Bus triggered azure function where a CdsServiceClient is being injected for each invoke using dependency injection. This instance is always cloned from a default one. When there are a lot of concurrent calls to the clone method, I've seen occasions where it took 30 secs for the clone method to return. Using the previous version (0.2.31-Alpha), I was not experiencing this.

So, I went to create a quick console app to test and do a lot of concurrent calls to the clone method (see gist) and this confirmed the behavior I was seeing.

Duration to clone:

0.2.31-Alpha	0.3.1-Alpha
avg: 4ms	avg: 4724ms
max: 33ms	max: 32002ms

Each run yields a different result but the duration between the 2 versions are significant.

[MattB-msft]

Thanks, that is nothing like we are seeing.

What version of functions are you using? And which os/runtime host are you using?

Also which auth type?

Would it be possible to share your function code so we can see how your setting up, to allow us to setup a similar test?

The clone code did not change substantially between msal and adal.net, the tokencaching behavior, however, was removed as msal's process is significantly different.

I am curious if there is a difference in msal between full framework and .core on Linux that may be at play here.

Thanks

[mathiasbl]

Azure Functions Core Tools
Core Tools Version: 3.0.3160 Commit hash: 00aa7f43cc5c5f15241b5e6e5363256f19ceb990
Function Runtime Version: 3.0.14916.0

Hosting on windows.
Using Client Secret as Auth type.

Repo to reproduce: https://github.com/mathiasbl/CdsServiceClient-Msal-Clone
Prepare a service bus queue and post 100+ messages on it, then fire up the function.

[MattB-msft]

@mathiasbl
We have seen this before and believe this has to do with the way lazy create is implemented in functions. there seems to be issue with the way network access is granted during the create flow, this causes the initial create of the CdsServiceClient to preform poorly. You should have seen this same behavior on older versions too.

if your OK with it, we will mod your function with a pattern we know to work well for this sort of flow and send you a PR?

thanks
MattB

[mathiasbl]

@MattB-msft I used to have problem creating the initial connection but was able to solve it using the lazy class or alternatively creating the connection on startup (see code below)

    var client = new CdsServiceClient(Environment.GetEnvironmentVariable("CdsServiceConnectionString"));
    builder.Services.AddSingleton(client);
    builder.Services.AddScoped<IOrganizationService>(sp => sp.GetRequiredService<CdsServiceClient>().Clone());

However, in the latest version cloning from the initial connection started giving problems in the MSAL release. Most likely since the caching is currently missing?

I'm very curious which pattern you use to make it work properly.

[MattB-msft]

if you read into the Lazy create and the remarks you will see this:
Use lazy initialization to defer the creation of a large or resource-intensive object, or the execution of a resource-intensive task, particularly when such creation or execution might not occur during the lifetime of the program.

The MSAL lib's use of in-memory cache and the way in which we pass around the Client object seem to trip the deferral described in the Lazy behavior.

You can actually see this if you trigger a single request.. pause for a few seconds and then dump several hundred / thousand requests in.

The first call will take many MS to create an clone... subsequent requests will take 10's or 100's of MS to create the clone.

If you boot it with a large number of requests in the queue, The lazy create / clone process hangs up the clone processes and seems to compile a large number of requests to the dispatcher, which will timeout the service bus connection and cause requeuing of several events.
Once it catchs up the performance of clone becomes 10's to 100's of MS for the clone.

If you create the connection outside of the lazy create and return it... you get much faster response.

[mathiasbl]

Thanks @MattB-msft for the feedback.

Looking forward to the PR with a pattern that works well for my scenario.

[BetimBeja]

I am just curious! Isn't it too much overhead using Lazy<CdsServiceClient>? Maybe a pattern like this is better for performance. I believe that AddSigleton correctly handles the Lazy initialization and adding another Lazy would only complicate the pipeline's optimizations.

[MattB-msft]

The issue with both patterns there is the use of the IOrganziationService for the instance.

When you clone, there are resources allocated that should be disposed of when your done with the connection. Using the IOrganization leaves those resources in memory until the thread is marked for deletion by functions and then cleaned up by the GC.

the way that we have been testing, and really need to get a sample posted, is a setup like this:

public class Startup : FunctionsStartup
{
    public override void Configure(IFunctionsHostBuilder builder)
    {
        CdsServiceClient client = null;
        if ( client == null )
        {
            client = GetClient(); // Set up the connection here. 
        }

        builder.Services.AddSingleton<CdsClientWithDate>(sp =>
        {
            return new CdsClientWithDate () { 
                localClient = client,
                createDate = DateTime.UtcNow};
        });

        builder.Services.AddScoped<CdsServiceClient>(sp =>
        {
            Stopwatch st = new Stopwatch();
            st.Restart();
            var ms01 = st.ElapsedMilliseconds;
            var logger = sp.GetRequiredService<ILogger<Startup>>();
            var ms02 = st.ElapsedMilliseconds;
            var client = sp.GetRequiredService<CdsClientWithDate>();
            var ms03 = st.ElapsedMilliseconds;
            var clone = client.localClient.Clone();
            var ms04 = st.ElapsedMilliseconds;
            logger.LogInformation($"Cloned client - {ms01} - {ms02} - {ms03} - {ms04}");
            st.Stop(); 
            st = null; 
            return clone;
        });
    }
    CdsServiceClient GetClient(ILogger<Startup> logger = null)
    {
        //TraceControlSettings.TraceLevel = System.Diagnostics.SourceLevels.All;
        //TraceControlSettings.AddTraceListener(new ConsoleTraceListener());
        logger?.LogInformation("Connecting to CDS");
        var connectionString = Environment.GetEnvironmentVariable("CdsServiceConnectionString");
        CdsServiceClient client = null;
        client = new CdsServiceClient(connectionString);
        if (client.IsReady)
        {
                logger?.LogInformation("Connected to CDS...");
                return client;
        }
        else throw client.LastCdsException;
   }
}

internal class CdsClientWithDate
{
    public CdsServiceClient localClient { get; set; }
    public DateTime createDate { get; set; }
    
}

Notice that the scoped ( or transient if you like ) is returning an instance of the CdsServiceClient, while the singleton is returning a custom storage class used to store the Single CdsServiceclient.

In the function implementation you then utilize it using the "using" pattern or add a .dispose to the client when your done with it.
That allows the functions host to more quickly release the resources for that execution and and optimize clean up.. which will also impact runtime costs with functions :)

With the examples above, there is the occasional 4 second clone process that is slowed down by the larger GC / heap Cleanup in the host process ( which seems to slow everything down), however the majority of clones are occurring with a 3 - 15 millisecond cost.

In my example and runs, I am using a .net 3.1 host on Windows with the Functions consumption plan.

[mathiasbl]

Thanks! Will implement this tomorrow and provide feedback.

Would it be beneficial to store already cloned instances in a sort of pool? So you can attempt to take an instance from the pool before you clone a new one.

[MattB-msft]

In my opinion, Connection pools are generally good idea to manage the concurrency of connections. Though it forces you ( the developer ) to understand the multi-threaded nature of the application and how threads need to interact.
We do recommend connection pools for high volume websites,

For functions, it is really a judgment call, as you can scale out functions fairly easily now and the functions and Asp.net teams have gone to great lengths to hide and automate the threading mechanics and challenges with these sorts of applications, thus the above mentioned singleton and scoped DI types.

In short, if you have a connection pool you end up having better control over the number of concurrent connections to the remote which allows you to manage port exhaustion issues. It also allows you to more closely manage throughput and if required have multiple different connections, potentially with different users, for different uses.

Again, its a judgement call based on your use case.

I have submitted a PR to your repro with our working example that we have been running against for the last day or so.
https://github.com/MattB-msft/CdsServiceClient-Msal-Clone/tree/users/mbarbour/testingCloneIssue

[MattB-msft]

@mathiasbl is this working for you?

[mathiasbl]

@MattB-msft I was testing this morning with your example and can confirm that it's working. However, when you disable the tracing I'm seeing the same behaviour as I was experiencing. With tracing enabled it looks ok.

        private CdsServiceClient GetClient()
        {
            //TraceControlSettings.TraceLevel = System.Diagnostics.SourceLevels.All;
            //TraceControlSettings.AddTraceListener(new ConsoleTraceListener());
            var client = new CdsServiceClient(Environment.GetEnvironmentVariable("CdsServiceConnectionString"));
            if (client.IsReady)
            {
                return client;
            }
            else
                throw client.LastCdsException;
        }

edit:
Putting the trace level to, for example, Information is also already enough to trip the behaviour.

[MattB-msft]

which behavior are you referring too?