logging-log4net-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Dominik Psenner (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter
Date Fri, 17 May 2013 06:41:15 GMT

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

Dominik Psenner commented on LOG4NET-376:
-----------------------------------------

Regarding ThreadStatic: I did not do performance timings, thus I do not know if it would perform
better. My believe is that this attribute could tear down performance in heavily cross-threaded
environments by practically disabling the cache. Generally I do not think it is wise to have
code behaving one way in multi threading and another way in single threading. It makes the
code terribly hard to maintain and therefore I would not want to take a foot on that road
unless there are good arguments to do so.

Regarding the drop of static: changing the cache to be instance specific would practically
make it ineffective since it would happen in every formatter instance whereas it needs to
be done only once every second. So that would have a performance impact too which probably
is bigger than a pure lock. The way Stefan fixed LOG4NET-323 seems to be perfectly fine to
me.

It is widely known that thread safety does not come for free. If you believe that the performance
impact is not neglectable I would like to encourage you to do some performance timings for
these scenarios:

* "Rev 1483378" in Single Thread
* "Rev 1380139 + ThreadStatic" in Single Thread
* "Rev 1483378" in Multi Thread
* "Rev 1380139 + ThreadStatic" in Multi Thread
                
> Race condition in AbsoluteTimeDateFormatter
> -------------------------------------------
>
>                 Key: LOG4NET-376
>                 URL: https://issues.apache.org/jira/browse/LOG4NET-376
>             Project: Log4net
>          Issue Type: Bug
>    Affects Versions: 1.2.11
>            Reporter: Stuart Lange
>            Assignee: Dominik Psenner
>             Fix For: 1.2.12
>
>
> AbsoluteTimeDateFormatter's caching of the "to the second" timestamp string is not thread-safe.
 It is possible for one thread to clear the check (that this timestamp matches the currently
cached "to the second" timestamp), but then end up using an incorrect "to the second" timestamp
string if another thread has changed it in the meantime.
> In our organization, we see this bug fairly regularly because we have a mix of "real
time" loggers that immediately write out log lines and "batching" loggers that defer logging
to a background task that runs every second.  We therefore regularly see log lines where the
timestamp is off by a second or two.
> The following unit tests demonstrates the bug:
>     [TestFixture]
>     [Explicit]
>     public class Log4netTimestampBug
>     {
>         /// <summary>
>         /// This test demonstrates a bug with the log4net default time formatter (Iso8601DateFormatter)
>         /// where the logged timestamp can be seconds off from the actual input timestamp
>         /// The bug is caused to a race condition in the base class AbsoluteTimeDateFormatter
>         /// because this class caches the timestamp string to the second but it is possible
for
>         /// the timestamp as written by a different thread to "sneak in" and be used
by another
>         /// thread erroneously (the checking and usage of this string is not done under
a lock, only
>         /// its modification) 
>         /// </summary>
>         [Test]
>         public void Test()
>         {
>             var now = DateTime.Now;
>             var times = Enumerable.Range(1, 1000000).Select(i => now.AddMilliseconds(i)).ToList();
>             var sb1 = new StringBuilder();
>             var sb2 = new StringBuilder();
>             var task1 = Task.Run(() => WriteAllTheTimes(times, new StringWriter(sb1)));
>             var task2 = Task.Delay(50).ContinueWith(t => WriteAllTheTimes(times, new
StringWriter(sb2)));
>             Task.WaitAll(task1, task2);
>             var task1Strings = GetTimeStrings(sb1);
>             var task2Strings = GetTimeStrings(sb2);
>             var diffs = Enumerable.Range(0, times.Count).Where(i => task1Strings[i]
!= task2Strings[i]).ToList();
>             Console.WriteLine("found {0} instances where the formatted timestamps are
not the same", diffs.Count);
>             Console.WriteLine();
>             var diffToLookAt = diffs.FirstOrDefault(i => i - 10 > 0 &&
i + 10 < times.Count);
>             if (diffToLookAt != 0)
>             {
>                 Console.WriteLine("Example Diff:");
>                 Console.WriteLine();
>                 Console.WriteLine("Index     Original Timestamp        Task 1 Format
            Task 2 Format");
>                 for (int i = diffToLookAt - 10; i < diffToLookAt + 10; i++)
>                 {
>                     Console.WriteLine("{0,-7}   {1}   {2}   {3}   {4}", i, times[i].ToString("yyyy-MM-dd
HH:mm:ss,fff"),
>                                       task1Strings[i], task2Strings[i], i == diffToLookAt
? "**** DIFF HERE ****" : "");
>                 }
>             }
>             CollectionAssert.AreEqual(task1Strings, task2Strings);
>         }
>         private static List<string> GetTimeStrings(StringBuilder sb1)
>         {
>             return sb1.ToString().Split(new[] {'\r', '\n'}, StringSplitOptions.RemoveEmptyEntries).ToList();
>         }
>         private static void WriteAllTheTimes(IEnumerable<DateTime> times,
>                                              TextWriter writer)
>         {
>             var formatter = new Iso8601DateFormatter();
>             foreach (var t in times)
>             {
>                 formatter.FormatDate(t, writer);
>                 writer.WriteLine();
>             }
>         }
>     }

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message