Task.WaitAll never ends If tasks are based on intercepted actions

pavel's Avatar

pavel

01 Aug, 2018 10:18 PM

Hello, Sharpcrafters!
We started to use PostSharp for interception based logging. Our product has a pretty long history. Hence, we have some pieces of legacy code. We can't spend much time on refactoring.
That is why the problem we encountered is crucial for us:
1) We have simple OnMethodBoundaryAspect-based logger;
2) We apply it to all our MVC controllers (for starters) via assembly attribute;
3) Simple, old code hangs onTask.WaitAll. It just never ends (!).
 var tasks = new[]
{
LogAction(() => DoJob(), "Job 1"),
        //...
LogAction(() => DoJob(), "Job 10"),
};
Task.WaitAll(tasks, 50000);
4) We tried to remove all code from interceptor - it didn't help.
We tried to tune scheduling - it didn't help.
We tried to simplify jobs, change platform - it didn't help.
Profiler shows that WaitAll is the only place where "something" happens 50 seconds.
You can check the attached test projects to reproduce the problem.
It occurs in WEB-HOSTED APPLICATION ONLY (PostSharp.Test.Web.csproj)!
PostSharp.Test.Console works fine.

Here is the example log output:
2018-08-02 00:09:17,578 - Test started
2018-08-02 00:09:17,623 - Job 2, 31 ms
2018-08-02 00:09:17,623 - Job 1, 33 ms
2018-08-02 00:09:17,627 - Job 4, 31 ms
2018-08-02 00:09:17,628 - Job 3, 32 ms
2018-08-02 00:09:17,629 - Job 5, 31 ms
2018-08-02 00:09:17,630 - Job 6, 31 ms
2018-08-02 00:09:17,631 - Job 7, 31 ms
2018-08-02 00:09:17,675 - Job 8, 51 ms
2018-08-02 00:09:17,675 - Job 9, 51 ms
2018-08-02 00:09:17,679 - Job 10, 51 ms
2018-08-02 00:10:07,597 - Test finished in 50 020 ms
You can see that WaitAll finished in ~50 seconds, but should - in ~1!

Best regards,
Pavel Borodaev
Canary Systems

  1. Support Staff 1 Posted by PostSharp Techn... on 02 Aug, 2018 09:56 AM

    PostSharp Technologies's Avatar

    Hello Pavel,

    the reason of this behavior is in advising of the LogAction method. Since the method returns an awaitable type, we internally await the result of this task before calling the OnExit method of your aspect, which causes deadlock in a web application since web applications handle awaiting in a different way than console applications.

    There's actually no control over how the await is called, but you can make PostSharp to not call the await at all. This is done by setting the SemanticallyAdvisedMethodKinds protected property of your aspect. See http://doc.postsharp.net/semantic-advising#disabling for details.

    In your sample, you can add the following constructor to your aspect to avoid the deadlock:

    public LoggingAspectAttribute()
    {
        this.SemanticallyAdvisedMethodKinds = 
            SemanticallyAdvisedMethodKinds.Async 
            | SemanticallyAdvisedMethodKinds.Iterator;
    }
    

    Does this solve your problem?

    Best regards,
    -tony

  2. 2 Posted by pavel on 02 Aug, 2018 11:21 AM

    pavel's Avatar

    Yes - it solves the problem. Thank you. Can you explain semantic advising? What method behaviors "magically provided" by PostSharp internally just by using interception (SemanticallyAdvisedMethodKinds.All)? There is no much information about it in online docs.
    And one extra question:
    Is it true, that the only way to exchange information between interception phases is using MethodExecutionArgs.MethodExecutionTag since aspect instance can be applied to different methods "simultaneously" - it is not possible to use aspect instance serializable (?) properties for such data exchange? Or each "interception scope" (set of stages) will have isolated aspect instance? For example: can I create and start stopwatch in OnEntry and then use it in OnSuccess?

  3. Support Staff 3 Posted by PostSharp Techn... on 02 Aug, 2018 01:56 PM

    PostSharp Technologies's Avatar

    As documented at http://doc.postsharp.net/t_postsharp_aspects_semanticallyadvisedmet..., by default, we apply semantic advising in 3 cases:
    1+2) Async methods and iterators. These methods get a state machine generated by the C# compiler and PostSharp weaves its logic into this state machine code.
    3) Methods returning object of an awaitable type (eg. Task). This is your case. Since there's no state machine there, PostSharp generates the state machine to be able to await the result of the task. This might not always be needed and that's why you need to change the default behavior in your case.

    To your second question: Yes, the MethodExecutionArgs.MethodExecutionTag is the best option. Otherwise you'd end up with a dictionary. Aspect instance is bound to a method by default. It can be bound to object instance, but this will not be thread safe, since the same method can be called on the same instance multiple times simultaneously. See http://doc.postsharp.net/t_postsharp_aspects_iinstancescopedaspect for instance-scoped aspects.

    Have you had a look at our Logging library? http://doc.postsharp.net/logging This provides you with logging aspect and custom logging out of the box. You can connect it to log4net and all these cumbersome details are solved for you.

    Best regards,
    -tony

  4. Support Staff 4 Posted by PostSharp Techn... on 14 Aug, 2018 03:39 PM

    PostSharp Technologies's Avatar

    Hello,

    We are going to close this request as there have not been any further updates. Please feel free to reopen the discussion if you need more help.

    Thanks,
    PostSharp Team

  5. PostSharp Technologies closed this discussion on 14 Aug, 2018 03:39 PM.

Comments are currently closed for this discussion. You can start a new one.

Keyboard shortcuts

Generic

? Show this help
ESC Blurs the current field

Comment Form

r Focus the comment reply box
^ + ↩ Submit the comment

You can use Command ⌘ instead of Control ^ on Mac