tdsharp
tdsharp copied to clipboard
egramtel
why so long?
Unfortunately, I cannot reproduce this behavior: in my case, this exact code works instantly.
What kind of application do you develop? Is this a UI app? Could there be some problem with your synchronization context?
Try adding .ConfigureAwait(false) after .ExecuteAsync(…).
Everything works in the console application. When I develop a WPF(.NET 5.0) application, some problems occur. Method ".ConfigureAwait(false)" didn't help :(
What does your UI application do during this method call? Could you please try profiling it, say in a timeline mode, or get thread dumps/call stacks via some other way while this activity is executing?
Same problem in UWP and MAUI. Each asynchronous request is executed in a separate thread, takes at least 40 seconds of time.
UPD. All authorization steps work fine, problems start after AuthorizationStateReady arrives.
UPD 2. It takes 25% of my i7's CPU time while waiting. This is normal?
I still suggest profiling the application.
Here. Base authorise. Created Client, sended TdApi.SetTdlibParameters, and TdApi.CheckDatabaseEncryptionKey. After sending TdApi.CheckDatabaseEncryptionKey, nothing arrive zip.zip
Regarding the slow message processing
I still have no clue. Does it reproduce without MAUI, in a simple console app you'd be able to share?
Regarding the CPU usage
Okay, this gets interesting.
What TdSharp does is calling native function ClientReceive with a small timeout in an endless loop: https://github.com/egramtel/tdsharp/blob/df48525c9b67050d96f48e1273127bc8b858c7a3/TdLib/Bindings/Receiver.cs#L46-L68
A small timeout (that's 0.1 sec) is required for the client to be able to terminate in a timely manner on a cancellation token termination.
I never thought 10 native calls per second would take so much CPU time (about 16% in the profile you provided). Do events happen often in your program? I.e. do you have much traffic?
Can you please try building tdsharp yourself and increase the timeout from 0.1 to 10 in this line of code? https://github.com/egramtel/tdsharp/blob/df48525c9b67050d96f48e1273127bc8b858c7a3/TdLib/Bindings/Receiver.cs#L48
Will the CPU consumption get smaller? Will the response time get better?
Yes, I already tried changing the timeout. Increasing it to 10 seconds reduces the load by about 5%. I have been debugging the project for two days now, this is what I was able to discover. All requests that do not require authorization work. Problems getting AuthorizationStateReady and beyond. Several times there was a situation when after several requests, which were executed from 40 seconds to 2 minutes, everything returned to normal, requests were made quickly, there was no load on the processor. What was the reason - I could not figure it out. Asynchronous requests are added to the
list private readonly ConcurrentDictionary<int, Action<TdApi.Object>> _tasks;
and are deleted when data arrives. Updates come without problems. In general, the code itself works as it should. It seems as if the problem is in tdjson.dll I will check the console project a little later, I will write how I get the result
Checked the console application. Works fine, no problems. This is really getting interesting :)
My guess would be that tdsharp is relying on global synchronization context somehow (this is obvious global difference between console and MAUI app). I think I've cleaned it all up in #92 and released as 1.7.0.1. Could you please check that you're using that (or a newer) version?
I was using version 1.8.1.1 from nuget Then linked the code from github to figure out what was wrong. Now checked Nuget 1.7. No changes, CPU load and long wait times
Eventually I was able to get it to work. Tried to figure out what could be wrong in TdJson, called
TdLibBindingsExtensions.SetLogFilePath
TdLibBindingsExtensions.SetLogVerbosityLevel
in the client constructor and everything worked. There are no delays, there is no load on the processor. I have no idea why :) Set TdLogLevel to Error so that logs take up less memory
Wow, that's unusual. Perhaps you had a lot of traffic, and logging took a significant amount of time? Even though the logs are usually going nowhere in a UI application.
Before this change, were you setting another log level?
I don't think there was much traffic. Basically just basic updates. Yes, I set "Info" first. The logs were fine. Not much time passed between the request and the answer. Turned off logs - delays again.
Same story for me. With 1.7 it was quite fast, with 1.8 it more than 30 seconds to load just 10 chats. Also same for the Connection events, using 1.7 I have about 3-5 seconds between Connecting and ConnectionReady, with 1.8 it more then 30 seconds (always). Here is the logs from 1.8, it almost a minute:
2022-08-17 08:38:47.1965|DEBUG|TelegramClient.TClient|connection state: $TdLib.TdApi+ConnectionState+ConnectionStateConnecting (connectionStateConnecting, )
2022-08-17 08:39:28.7697|DEBUG|TelegramClient.TClient|connection state: $TdLib.TdApi+ConnectionState+ConnectionStateUpdating (connectionStateUpdating, )
2022-08-17 08:39:36.5610|DEBUG|TelegramClient.TClient|connection state: $TdLib.TdApi+ConnectionState+ConnectionStateReady (connectionStateReady, )
PS Migration from 1.7 to 1.8.1 fully failed, reverted back.
Using
TdLibBindingsExtensions.SetLogFilePath
TdLibBindingsExtensions.SetLogVerbosityLevel
solved for me both issues
I wasn't still able to reproduce the issue. I guess at this stage someone has to upload a public source snippet for us to reproduce this, so we'll be able to either diagnose or fix it.
@ForNeVeR you now have access to the private repo. Please upgrade the packages to 1.8 and uncomment the code at MainWindow.xaml.cs line 178. Sorry for the code quality, this is just a quick PoC. Fill free to ask any questions, or if I need to push the 1.8 code.
@ForNeVeR also pushed the tdlib_1_8 branch, you can take it. Just remove line line 46-47 at \TClient\TClient.cs to repro the issue. Thank you.
Small update: with SetLogFilePath and SetLogVerbosityLevel the TDLib working INCREDIBLE fast! Every single event, every call to TDLib function now happened almost instant. I'm impress from one hand and I bit warried from another. Before changes the entire warm up of the app took about 2-3 minutes (connection, loadChats, waiting until chats loaded in UpdateNewChat).
Now it took 9 (!!!!) seconds
2022-08-17 21:30:31.3935|DEBUG|TelegramClient.TClient|Waiting connection init...
........
2022-08-17 21:30:40.3587|DEBUG|TelegramClient.TClient|Unhanled update: TdLib.TdApi+Update+UpdateChatPosition
Same log without "magic settings":
2022-08-17 21:33:15.8997|DEBUG|TelegramClient.TClient|Waiting connection init...
........
2022-08-17 21:36:18.0911|DEBUG|TelegramClient.TClient|Unhanled update: TdLib.TdApi+Update+UpdateChatPosition
and another update (sorry for spamming): SetLogVerbosityLevel is enough to make it work fast.
I see such magic for the first time :) Perhaps it is worth adhering to the principle "It works - do not touch it", add logging by default to the client's constructor and leave it that way?
You use that in a GUI app with no console, right?
Yes, MAUI. Now I've repackaged this library to the MAUI class library, use .Net 6.0.
@antonGritsenko, your program (or at least the version which is slow) seems to use GetAwaiter().GetResult() a lot. And also, there's a lot of async void, which I cannot approve.
Most likely, the reason is this GetAwaiter().GetResult(). This action may take any amount of time (depending on the target synchronization context) or even cause a deadlock. Especially if you call it in TdClient::UpdateReceived handler (which calls its subscribers synchronously inside of the client event loop).
@nikolaykusch, is there a chance you have any Task.Result or GetAwaiter().GetResult() calls in your program as well?
@ForNeVeR the async void is the normal practice for the event handlers in WPF. Actually, there is no choice there.
No it is not, and I forbid you to use async void in any context. Just don't. It is bad.