[jira] [Commented] (LOG4NET-562) LogicalThreadContext is not per Thread

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[jira] [Commented] (LOG4NET-562) LogicalThreadContext is not per Thread

JIRA jira@apache.org

    [ https://issues.apache.org/jira/browse/LOG4NET-562?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15960445#comment-15960445 ]

Dominik Psenner commented on LOG4NET-562:
-----------------------------------------

Have you tried to include the actual thread that the code executes in by logging System.Threading.Thread.CurrentThread.ManagedThreadId?

> LogicalThreadContext is not per Thread
> --------------------------------------
>
>                 Key: LOG4NET-562
>                 URL: https://issues.apache.org/jira/browse/LOG4NET-562
>             Project: Log4net
>          Issue Type: Bug
>          Components: Other
>    Affects Versions: 2.0.8
>         Environment: Windows 10, Visual Studio 17, .NET Framework 4.5.2
>            Reporter: Husain Alshehhi
>
> LogicalThreadContext values are spread to many threads when they shouldn't.
> This is an example:
> {code:title=console.cs|borderStyle=solid}
>             LogicalThreadContext.Properties["x-corralation-Id"] = "original-value";
>             var list = new List<int> {1, 2, 3, 4, 5, 6, 7, 8, 9, 0};
>             Parallel.ForEach(list, (i) =>
>             {
>                 if (i == 3)
>                     LogicalThreadContext.Properties["x-corralation-Id"] = "modified-value";
>                 logger.Info($"thread {i}.");
>             });
> {code}
> this is the result
> {code:title=badresult.txt|borderStyle=solid}
> {"timestamp":"2017-04-05T12:31:41.117Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 1.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.132Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 3.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 4.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 6.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 8.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 0.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.219Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 7.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.179Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 5.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 2.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.234Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 9.", "data":(null)}
> {code}
> This is what I was expecting:
> {code:title=goodresult.txt|borderStyle=solid}
> {"timestamp":"2017-04-05T12:31:41.117Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 1.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.132Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 3.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 4.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 6.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 8.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 0.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.219Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 7.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.179Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 5.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 2.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.234Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 9.", "data":(null)}
> {code}



--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [jira] [Commented] (LOG4NET-562) LogicalThreadContext is not per Thread

Alexander Houben
Hello Husain,

I think the observed behavior lies in the implementation of Parallel.ForEach. All your assumptions seem correct to me except that Parallel.ForEach does not execute its actions on a separate thread or separate task each.

If you look at mscorlib with ILSpy and find System.Threading.Tasks.Parallel.ForEach you'll see that it does some heavy optimization to find the right ratio of threads/tasks and load.

IMHO it may be reusing a task where your "x-correlation-id" was set (if (i==3)) for other values of i, this is why you are seeing multiple modified log outputs.

cheers,
alex

On Fri, Apr 7, 2017 at 10:04 AM, Dominik Psenner (JIRA) <[hidden email]> wrote:

    [ https://issues.apache.org/jira/browse/LOG4NET-562?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15960445#comment-15960445 ]

Dominik Psenner commented on LOG4NET-562:
-----------------------------------------

Have you tried to include the actual thread that the code executes in by logging System.Threading.Thread.CurrentThread.ManagedThreadId?

> LogicalThreadContext is not per Thread
> --------------------------------------
>
>                 Key: LOG4NET-562
>                 URL: https://issues.apache.org/jira/browse/LOG4NET-562
>             Project: Log4net
>          Issue Type: Bug
>          Components: Other
>    Affects Versions: 2.0.8
>         Environment: Windows 10, Visual Studio 17, .NET Framework 4.5.2
>            Reporter: Husain Alshehhi
>
> LogicalThreadContext values are spread to many threads when they shouldn't.
> This is an example:
> {code:title=console.cs|borderStyle=solid}
>             LogicalThreadContext.Properties["x-corralation-Id"] = "original-value";
>             var list = new List<int> {1, 2, 3, 4, 5, 6, 7, 8, 9, 0};
>             Parallel.ForEach(list, (i) =>
>             {
>                 if (i == 3)
>                     LogicalThreadContext.Properties["x-corralation-Id"] = "modified-value";
>                 logger.Info($"thread {i}.");
>             });
> {code}
> this is the result
> {code:title=badresult.txt|borderStyle=solid}
> {"timestamp":"2017-04-05T12:31:41.117Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 1.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.132Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 3.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 4.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 6.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 8.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 0.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.219Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 7.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.179Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 5.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 2.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.234Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 9.", "data":(null)}
> {code}
> This is what I was expecting:
> {code:title=goodresult.txt|borderStyle=solid}
> {"timestamp":"2017-04-05T12:31:41.117Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 1.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.132Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 3.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 4.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 6.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 8.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 0.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.219Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 7.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.179Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 5.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 2.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.234Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 9.", "data":(null)}
> {code}



--
This message was sent by Atlassian JIRA
(v6.3.15#6346)



--
Alexander Houben
Head of Engineering

Phone <a href="tel:%2B41-43%2020%2040%20812" value="+41432040812" style="color:rgb(17,85,204);font-size:12.8000001907349px" target="_blank">+41-43 20 40 812
Mobile <a href="tel:%2B41-79%20749%2030%2073" value="+41797493073" style="color:rgb(17,85,204);font-size:12.8000001907349px" target="_blank">+41-79 749 30 73
Email [hidden email]

Greenliff AG, Technoparkstrasse 1, CH-8005 Zürich, www.greenliff.com
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [jira] [Commented] (LOG4NET-562) LogicalThreadContext is not per Thread

Dominik Psenner

Thanks Alexander, that's exactly what I was suspecting. Parallel.ForEach() may not necessarily be using different threads to execute the tasks. Also, the latest stuff that can be implemented with async/await levers high parallelism without the need of multithreading. Only I'm afraid you have to post this on JIRA as well because Husain is probably not subscribed to the mailing list.


On 2017-04-07 10:31, Alexander Houben wrote:
Hello Husain,

I think the observed behavior lies in the implementation of Parallel.ForEach. All your assumptions seem correct to me except that Parallel.ForEach does not execute its actions on a separate thread or separate task each.

If you look at mscorlib with ILSpy and find System.Threading.Tasks.Parallel.ForEach you'll see that it does some heavy optimization to find the right ratio of threads/tasks and load.

IMHO it may be reusing a task where your "x-correlation-id" was set (if (i==3)) for other values of i, this is why you are seeing multiple modified log outputs.

cheers,
alex

On Fri, Apr 7, 2017 at 10:04 AM, Dominik Psenner (JIRA) <[hidden email]> wrote:

    [ https://issues.apache.org/jira/browse/LOG4NET-562?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15960445#comment-15960445 ]

Dominik Psenner commented on LOG4NET-562:
-----------------------------------------

Have you tried to include the actual thread that the code executes in by logging System.Threading.Thread.CurrentThread.ManagedThreadId?

> LogicalThreadContext is not per Thread
> --------------------------------------
>
>                 Key: LOG4NET-562
>                 URL: https://issues.apache.org/jira/browse/LOG4NET-562
>             Project: Log4net
>          Issue Type: Bug
>          Components: Other
>    Affects Versions: 2.0.8
>         Environment: Windows 10, Visual Studio 17, .NET Framework 4.5.2
>            Reporter: Husain Alshehhi
>
> LogicalThreadContext values are spread to many threads when they shouldn't.
> This is an example:
> {<a class="moz-txt-link-freetext" href="code:title=console.cs|">code:title=console.cs|borderStyle=solid}
>             LogicalThreadContext.Properties["x-corralation-Id"] = "original-value";
>             var list = new List<int> {1, 2, 3, 4, 5, 6, 7, 8, 9, 0};
>             Parallel.ForEach(list, (i) =>
>             {
>                 if (i == 3)
>                     LogicalThreadContext.Properties["x-corralation-Id"] = "modified-value";
>                 logger.Info($"thread {i}.");
>             });
> {code}
> this is the result
> {<a class="moz-txt-link-freetext" href="code:title=badresult.txt|">code:title=badresult.txt|borderStyle=solid}
> {"timestamp":"2017-04-05T12:31:41.117Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 1.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.132Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 3.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 4.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 6.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 8.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 0.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.219Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 7.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.179Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 5.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 2.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.234Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 9.", "data":(null)}
> {code}
> This is what I was expecting:
> {<a class="moz-txt-link-freetext" href="code:title=goodresult.txt|">code:title=goodresult.txt|borderStyle=solid}
> {"timestamp":"2017-04-05T12:31:41.117Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 1.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.132Z", "level":"INFO", "x-corralation-Id" : "modified-value", "logger":"logger", "message":"thread 3.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 4.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 6.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 8.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 0.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.219Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 7.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.179Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 5.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 2.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.234Z", "level":"INFO", "x-corralation-Id" : "original-value", "logger":"logger", "message":"thread 9.", "data":(null)}
> {code}



--
This message was sent by Atlassian JIRA
(v6.3.15#6346)



--
Alexander Houben
Head of Engineering

Phone <a moz-do-not-send="true" href="tel:%2B41-43%2020%2040%20812" value="+41432040812" style="color:rgb(17,85,204);font-size:12.8000001907349px" target="_blank">+41-43 20 40 812
Mobile <a moz-do-not-send="true" href="tel:%2B41-79%20749%2030%2073" value="+41797493073" style="color:rgb(17,85,204);font-size:12.8000001907349px" target="_blank">+41-79 749 30 73
Email [hidden email]

Greenliff AG, Technoparkstrasse 1, CH-8005 Zürich, www.greenliff.com

Loading...