is it possible log4net writes things out of order in a multithreaded app
.everyoneloves__top-leaderboard:empty,.everyoneloves__mid-leaderboard:empty,.everyoneloves__bot-mid-leaderboard:empty{ height:90px;width:728px;box-sizing:border-box;
}
I have a multithreaded C# app for which we use common.logging/log4net. while the logs read reasonably as one would expect, the timestamps can be pretty far off. I'm questioning if I can trust what I see, in terms of order of operations.
In this case I'm tracking memory and resetting my ConsumerUI. In the T09:27 entry I have lots of memory, in the next entry, T04:27 I don't. But you'll notice the T04 timestamp precedes the prior log entry by like 5 hours.
I've added diagnostic code to see if the log statements are truly out of order they are not. A timestamp arrives that is simply wrong.
What is going on here?
c# log4net
asked Nov 16 '18 at 20:55
jeffjeff
1,88312033
add a comment |
I have a multithreaded C# app for which we use common.logging/log4net. while the logs read reasonably as one would expect, the timestamps can be pretty far off. I'm questioning if I can trust what I see, in terms of order of operations.
In this case I'm tracking memory and resetting my ConsumerUI. In the T09:27 entry I have lots of memory, in the next entry, T04:27 I don't. But you'll notice the T04 timestamp precedes the prior log entry by like 5 hours.
I've added diagnostic code to see if the log statements are truly out of order they are not. A timestamp arrives that is simply wrong.
What is going on here?
c# log4net
asked Nov 16 '18 at 20:55
jeffjeff
1,88312033
What type of appender is creating that output? Is there only a single process logging? What is the log4net locking strategy (if a file appender)?
– sellotape
Nov 16 '18 at 21:04
I've added the appender to question. Minimal lock.
– jeff
Nov 16 '18 at 21:09
No forwarding appenders configured?
– sellotape
Nov 16 '18 at 21:43
at root there, is a debug appender and this rollinglogfile appender that's it. both out of the box appenders.
– jeff
Nov 16 '18 at 21:55
Honestly you shouldn't care. Logging is pure data, just like any data source if you need to sort it then sort it when you need to present it.
– Erik Philips
Nov 16 '18 at 23:13
add a comment |
I have a multithreaded C# app for which we use common.logging/log4net. while the logs read reasonably as one would expect, the timestamps can be pretty far off. I'm questioning if I can trust what I see, in terms of order of operations.
In this case I'm tracking memory and resetting my ConsumerUI. In the T09:27 entry I have lots of memory, in the next entry, T04:27 I don't. But you'll notice the T04 timestamp precedes the prior log entry by like 5 hours.
I've added diagnostic code to see if the log statements are truly out of order they are not. A timestamp arrives that is simply wrong.
What is going on here?
c# log4net
asked Nov 16 '18 at 20:55
jeffjeff
1,88312033
I have a multithreaded C# app for which we use common.logging/log4net. while the logs read reasonably as one would expect, the timestamps can be pretty far off. I'm questioning if I can trust what I see, in terms of order of operations.
In this case I'm tracking memory and resetting my ConsumerUI. In the T09:27 entry I have lots of memory, in the next entry, T04:27 I don't. But you'll notice the T04 timestamp precedes the prior log entry by like 5 hours.
I've added diagnostic code to see if the log statements are truly out of order they are not. A timestamp arrives that is simply wrong.
What is going on here?
c# log4net
c# log4net
asked Nov 16 '18 at 20:55
jeffjeff
1,88312033
asked Nov 16 '18 at 20:55
jeffjeff
1,88312033
edited Dec 7 '18 at 14:21
jeff
asked Nov 16 '18 at 20:55
jeffjeff
1,88312033
asked Nov 16 '18 at 20:55
jeffjeff
1,88312033
asked Nov 16 '18 at 20:55
jeffjeff
1,88312033
1,88312033
What type of appender is creating that output? Is there only a single process logging? What is the log4net locking strategy (if a file appender)?
– sellotape
Nov 16 '18 at 21:04
I've added the appender to question. Minimal lock.
– jeff
Nov 16 '18 at 21:09
No forwarding appenders configured?
– sellotape
Nov 16 '18 at 21:43
at root there, is a debug appender and this rollinglogfile appender that's it. both out of the box appenders.
– jeff
Nov 16 '18 at 21:55
Honestly you shouldn't care. Logging is pure data, just like any data source if you need to sort it then sort it when you need to present it.
– Erik Philips
Nov 16 '18 at 23:13
add a comment |
What type of appender is creating that output? Is there only a single process logging? What is the log4net locking strategy (if a file appender)?
– sellotape
Nov 16 '18 at 21:04
I've added the appender to question. Minimal lock.
– jeff
Nov 16 '18 at 21:09
No forwarding appenders configured?
– sellotape
Nov 16 '18 at 21:43
at root there, is a debug appender and this rollinglogfile appender that's it. both out of the box appenders.
– jeff
Nov 16 '18 at 21:55
Honestly you shouldn't care. Logging is pure data, just like any data source if you need to sort it then sort it when you need to present it.
– Erik Philips
Nov 16 '18 at 23:13
What type of appender is creating that output? Is there only a single process logging? What is the log4net locking strategy (if a file appender)?
– sellotape
Nov 16 '18 at 21:04
What type of appender is creating that output? Is there only a single process logging? What is the log4net locking strategy (if a file appender)?
– sellotape
Nov 16 '18 at 21:04
I've added the appender to question. Minimal lock.
– jeff
Nov 16 '18 at 21:09
I've added the appender to question. Minimal lock.
– jeff
Nov 16 '18 at 21:09
No forwarding appenders configured?
– sellotape
Nov 16 '18 at 21:43
No forwarding appenders configured?
– sellotape
Nov 16 '18 at 21:43
at root there, is a debug appender and this rollinglogfile appender that's it. both out of the box appenders.
– jeff
Nov 16 '18 at 21:55
at root there, is a debug appender and this rollinglogfile appender that's it. both out of the box appenders.
– jeff
Nov 16 '18 at 21:55
Honestly you shouldn't care. Logging is pure data, just like any data source if you need to sort it then sort it when you need to present it.
– Erik Philips
Nov 16 '18 at 23:13
Honestly you shouldn't care. Logging is pure data, just like any data source if you need to sort it then sort it when you need to present it.
– Erik Philips
Nov 16 '18 at 23:13
add a comment |
2 Answers
2
active
oldest
votes
Yes. All logging is Async. Its up to the log reader to correllate a coherent time sequence from the log files written. If this wasnt the case, logging would impost a hideous syncblock on an otherwise multithreaded application.
answered Nov 16 '18 at 23:02
PhillipHPhillipH
5,4661923
add a comment |
Depending on your log target configuration, the order of logged operations may be very far off. Typically for DB, file, or other expensive IO logging targets, a buffering Async wrapper is used, which will write to the IO target in batches, depending on usage. So it is fairly common to have the order that they get flushed not match the order that they were logged.
We always order our logs by the dateLoggedUTC (our field for that date) in order to really understand the order of operations.
answered Nov 16 '18 at 21:04
TimTim
2,2041715
when you say order by dateLoggedUTC, is that something I can set in the config file?
– jeff
Nov 16 '18 at 21:10
%utcdate{ABSOLUTE} is what we use. And our records are in a DB, not a text file
– Tim
Nov 16 '18 at 21:34
Indeed, the time difference is very close to 5 hours. Could really by a time zone thing.
– Klaus Gütter
Nov 17 '18 at 7:12
add a comment |
Your Answer
StackExchange.ifUsing("editor", function () {
StackExchange.using("externalEditor", function () {
StackExchange.using("snippets", function () {
StackExchange.snippets.init();
});
});
}, "code-snippets");
StackExchange.ready(function() {
var channelOptions = {
tags: "".split(" "),
id: "1"
};
initTagRenderer("".split(" "), "".split(" "), channelOptions);
StackExchange.using("externalEditor", function() {
// Have to fire editor after snippets, if snippets enabled
if (StackExchange.settings.snippets.snippetsEnabled) {
StackExchange.using("snippets", function() {
createEditor();
});
}
else {
createEditor();
}
});
function createEditor() {
StackExchange.prepareEditor({
heartbeatType: 'answer',
autoActivateHeartbeat: false,
convertImagesToLinks: true,
noModals: true,
showLowRepImageUploadWarning: true,
reputationToPostImages: 10,
bindNavPrevention: true,
postfix: "",
imageUploader: {
brandingHtml: "Powered by u003ca class="icon-imgur-white" href="https://imgur.com/"u003eu003c/au003e",
contentPolicyHtml: "User contributions licensed under u003ca href="https://creativecommons.org/licenses/by-sa/3.0/"u003ecc by-sa 3.0 with attribution requiredu003c/au003e u003ca href="https://stackoverflow.com/legal/content-policy"u003e(content policy)u003c/au003e",
allowUrls: true
},
onDemand: true,
discardSelector: ".discard-answer"
,immediatelyShowMarkdownHelp:true
});
}
});
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
StackExchange.ready(
function () {
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fstackoverflow.com%2fquestions%2f53345247%2fis-it-possible-log4net-writes-things-out-of-order-in-a-multithreaded-app%23new-answer', 'question_page');
}
);
Post as a guest
Required, but never shown
2 Answers
2
active
oldest
votes
2 Answers
2
active
oldest
votes
active
oldest
votes
active
oldest
votes
Yes. All logging is Async. Its up to the log reader to correllate a coherent time sequence from the log files written. If this wasnt the case, logging would impost a hideous syncblock on an otherwise multithreaded application.
answered Nov 16 '18 at 23:02
PhillipHPhillipH
5,4661923
add a comment |
Yes. All logging is Async. Its up to the log reader to correllate a coherent time sequence from the log files written. If this wasnt the case, logging would impost a hideous syncblock on an otherwise multithreaded application.
answered Nov 16 '18 at 23:02
PhillipHPhillipH
5,4661923
add a comment |
Yes. All logging is Async. Its up to the log reader to correllate a coherent time sequence from the log files written. If this wasnt the case, logging would impost a hideous syncblock on an otherwise multithreaded application.
answered Nov 16 '18 at 23:02
PhillipHPhillipH
5,4661923
Yes. All logging is Async. Its up to the log reader to correllate a coherent time sequence from the log files written. If this wasnt the case, logging would impost a hideous syncblock on an otherwise multithreaded application.
answered Nov 16 '18 at 23:02
PhillipHPhillipH
5,4661923
answered Nov 16 '18 at 23:02
PhillipHPhillipH
5,4661923
answered Nov 16 '18 at 23:02
PhillipHPhillipH
5,4661923
answered Nov 16 '18 at 23:02
PhillipHPhillipH
5,4661923
5,4661923
add a comment |
add a comment |
Depending on your log target configuration, the order of logged operations may be very far off. Typically for DB, file, or other expensive IO logging targets, a buffering Async wrapper is used, which will write to the IO target in batches, depending on usage. So it is fairly common to have the order that they get flushed not match the order that they were logged.
We always order our logs by the dateLoggedUTC (our field for that date) in order to really understand the order of operations.
answered Nov 16 '18 at 21:04
TimTim
2,2041715
when you say order by dateLoggedUTC, is that something I can set in the config file?
– jeff
Nov 16 '18 at 21:10
%utcdate{ABSOLUTE} is what we use. And our records are in a DB, not a text file
– Tim
Nov 16 '18 at 21:34
Indeed, the time difference is very close to 5 hours. Could really by a time zone thing.
– Klaus Gütter
Nov 17 '18 at 7:12
add a comment |
Depending on your log target configuration, the order of logged operations may be very far off. Typically for DB, file, or other expensive IO logging targets, a buffering Async wrapper is used, which will write to the IO target in batches, depending on usage. So it is fairly common to have the order that they get flushed not match the order that they were logged.
We always order our logs by the dateLoggedUTC (our field for that date) in order to really understand the order of operations.
answered Nov 16 '18 at 21:04
TimTim
2,2041715
when you say order by dateLoggedUTC, is that something I can set in the config file?
– jeff
Nov 16 '18 at 21:10
%utcdate{ABSOLUTE} is what we use. And our records are in a DB, not a text file
– Tim
Nov 16 '18 at 21:34
Indeed, the time difference is very close to 5 hours. Could really by a time zone thing.
– Klaus Gütter
Nov 17 '18 at 7:12
add a comment |
Depending on your log target configuration, the order of logged operations may be very far off. Typically for DB, file, or other expensive IO logging targets, a buffering Async wrapper is used, which will write to the IO target in batches, depending on usage. So it is fairly common to have the order that they get flushed not match the order that they were logged.
We always order our logs by the dateLoggedUTC (our field for that date) in order to really understand the order of operations.
answered Nov 16 '18 at 21:04
TimTim
2,2041715
Depending on your log target configuration, the order of logged operations may be very far off. Typically for DB, file, or other expensive IO logging targets, a buffering Async wrapper is used, which will write to the IO target in batches, depending on usage. So it is fairly common to have the order that they get flushed not match the order that they were logged.
We always order our logs by the dateLoggedUTC (our field for that date) in order to really understand the order of operations.
answered Nov 16 '18 at 21:04
TimTim
2,2041715
answered Nov 16 '18 at 21:04
TimTim
2,2041715
answered Nov 16 '18 at 21:04
TimTim
2,2041715
answered Nov 16 '18 at 21:04
TimTim
2,2041715
2,2041715
when you say order by dateLoggedUTC, is that something I can set in the config file?
– jeff
Nov 16 '18 at 21:10
%utcdate{ABSOLUTE} is what we use. And our records are in a DB, not a text file
– Tim
Nov 16 '18 at 21:34
Indeed, the time difference is very close to 5 hours. Could really by a time zone thing.
– Klaus Gütter
Nov 17 '18 at 7:12
add a comment |
when you say order by dateLoggedUTC, is that something I can set in the config file?
– jeff
Nov 16 '18 at 21:10
%utcdate{ABSOLUTE} is what we use. And our records are in a DB, not a text file
– Tim
Nov 16 '18 at 21:34
Indeed, the time difference is very close to 5 hours. Could really by a time zone thing.
– Klaus Gütter
Nov 17 '18 at 7:12
when you say order by dateLoggedUTC, is that something I can set in the config file?
– jeff
Nov 16 '18 at 21:10
when you say order by dateLoggedUTC, is that something I can set in the config file?
– jeff
Nov 16 '18 at 21:10
%utcdate{ABSOLUTE} is what we use. And our records are in a DB, not a text file
– Tim
Nov 16 '18 at 21:34
%utcdate{ABSOLUTE} is what we use. And our records are in a DB, not a text file
– Tim
Nov 16 '18 at 21:34
Indeed, the time difference is very close to 5 hours. Could really by a time zone thing.
– Klaus Gütter
Nov 17 '18 at 7:12
Indeed, the time difference is very close to 5 hours. Could really by a time zone thing.
– Klaus Gütter
Nov 17 '18 at 7:12
add a comment |
Thanks for contributing an answer to Stack Overflow!
- Please be sure to answer the question. Provide details and share your research!
But avoid …
- Asking for help, clarification, or responding to other answers.
- Making statements based on opinion; back them up with references or personal experience.
To learn more, see our tips on writing great answers.
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
StackExchange.ready(
function () {
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fstackoverflow.com%2fquestions%2f53345247%2fis-it-possible-log4net-writes-things-out-of-order-in-a-multithreaded-app%23new-answer', 'question_page');
}
);
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
What type of appender is creating that output? Is there only a single process logging? What is the log4net locking strategy (if a file appender)?
– sellotape
Nov 16 '18 at 21:04
I've added the appender to question. Minimal lock.
– jeff
Nov 16 '18 at 21:09
No forwarding appenders configured?
– sellotape
Nov 16 '18 at 21:43
at root there, is a debug appender and this rollinglogfile appender that's it. both out of the box appenders.
– jeff
Nov 16 '18 at 21:55
Honestly you shouldn't care. Logging is pure data, just like any data source if you need to sort it then sort it when you need to present it.
– Erik Philips
Nov 16 '18 at 23:13