logging considered-harmful
TRANSCRIPT
Logging - Considered Harmful?
David Dancy Programmation Pty Limited
@4dexpert
Race Conditions
Racing C#
Racing C#initial = 100
Racing C#initial = 100
-0
100
Racing C#initial = 100
+1
101
-0
100
Racing C#initial = 100
+1
101
-2
99
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
+7
104
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
+7
104
-8
96
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
+7
104
-8
96
+9
105
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
+7
104
-8
96
+9
105
-10
95
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
+7
104
-8
96
+9
105
-10
95
+11
106
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
+7
104
-8
96
+9
105
-10
95
+11
106
-12
94
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
+7
104
-8
96
+9
105
-10
95
+11
106
-12
94
+13
107
-0
100
Racing C#initial = 100
+1
101
-2
99
+3
102
-4
98
+5
103
-6
97
+7
104
-8
96
+9
105
-10
95
+11
106
-12
94
+13
107
-14
93
-0
100
Racing C#[44006:6972073][2015-08-10T22:14:23.5812750Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 0 [44006:6972073][2015-08-10T22:14:23.5812830Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 1 [44006:6972073][2015-08-10T22:14:23.5812890Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 2 [44006:6972073][2015-08-10T22:14:23.5812940Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 3 [44006:6972073][2015-08-10T22:14:23.5812990Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 4 [44006:6972073][2015-08-10T22:14:23.5813050Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 5 [44006:6972073][2015-08-10T22:14:23.5813110Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 6 [44006:6972073][2015-08-10T22:14:23.5813160Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 7 [44006:6972073][2015-08-10T22:14:23.5813200Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 8 [44006:6972073][2015-08-10T22:14:23.5813260Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 9 [44006:6972073][2015-08-10T22:14:23.5813310Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 10 [44006:6972073][2015-08-10T22:14:23.5813360Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 11 [44006:6972073][2015-08-10T22:14:23.5813400Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 12 [44006:6972073][2015-08-10T22:14:23.5813450Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 13 [44006:6972073][2015-08-10T22:14:23.5813500Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 14 [44006:6972073][2015-08-10T22:14:23.5813610Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L146]: -> 93
Racing C#initial = 100
Racing C#initial = 100
-0
100
Racing C#initial = 100
-0
100
+1
101
Racing C#initial = 100
-0
100
+1
101
+3
104
Racing C#initial = 100
-2
102
-0
100
+1
101
+3
104
Racing C#initial = 100
-2
102
-0
100
+1
101
+3
104
-4
98
Racing C#initial = 100
-2
102
+5
103
-0
100
+1
101
+3
104
-4
98
Racing C#initial = 100
-2
102
+5
103
-6
97
-0
100
+1
101
+3
104
-4
98
Racing C#initial = 100
-2
102
+7
104
+5
103
-6
97
-0
100
+1
101
+3
104
-4
98
Racing C#initial = 100
-2
102
+7
104
+5
103
-6
97
-0
100
+1
101
+3
104
+9
113
-4
98
Racing C#initial = 100
-2
102
+7
104
+5
103
-6
97
-0
100
+1
101
-10
93
+3
104
+9
113
-4
98
Racing C#initial = 100
-2
102
+7
104
+5
103
-6
97
-0
100
+11
104
+1
101
-10
93
+3
104
+9
113
-4
98
Racing C#initial = 100
-2
102
+7
104
+5
103
-6
97
-0
100
+11
104
-8
96
+1
101
-10
93
+3
104
+9
113
-4
98
Racing C#initial = 100
-2
102
+7
104
+5
103
-6
97
-0
100
+11
104
-8
96
+1
101
-10
93
+3
104
-12
84
+9
113
-4
98
Racing C#initial = 100
-2
102
+7
104
+5
103
-6
97
-0
100
+11
104
-8
96
+1
101
-10
93
+3
104
+13
97
-12
84
+9
113
-4
98
Racing C#initial = 100
-2
102
+7
104
+5
103
-6
97
-0
100
+11
104
-8
96
+1
101
-10
93
+3
104
+13
97
-12
84
+9
113
-14
83
-4
98
Racing C#[44006:6972073][2015-08-10T22:14:23.5816070Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 0 [44006:6972073][2015-08-10T22:14:23.5816250Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 1 [44006:6972073][2015-08-10T22:14:23.5816310Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 3 [44006:6972073][2015-08-10T22:14:23.5816310Z][DBUG00009][ViewModels.RaceLoggingViewModel.Run L138]: 2 [44006:6972073][2015-08-10T22:14:23.5816360Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 4 [44006:6972073][2015-08-10T22:14:23.5816410Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 5 [44006:6972073][2015-08-10T22:14:23.5816460Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 6 [44006:6972073][2015-08-10T22:14:23.5816500Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 7 [44006:6972073][2015-08-10T22:14:23.5816550Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 9 [44006:6972073][2015-08-10T22:14:23.5816600Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 10 [44006:6972073][2015-08-10T22:14:23.5816640Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 11 [44006:6972073][2015-08-10T22:14:23.5816680Z][DBUG00009][ViewModels.RaceLoggingViewModel.Run L138]: 8 [44006:6972073][2015-08-10T22:14:23.5816690Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 12 [44006:6972073][2015-08-10T22:14:23.5816740Z][DBUG00010][ViewModels.RaceLoggingViewModel.Run L138]: 13 [44006:6972073][2015-08-10T22:14:23.5816910Z][DBUG00009][ViewModels.RaceLoggingViewModel.Run L138]: 14 [44006:6972073][2015-08-10T22:14:23.5817100Z][DBUG00009][ViewModels.RaceLoggingViewModel.Run L146]: -> 92
Racing C#
Racing C#
Racing C#
Fixed!
????
Accidental Locks
Accidental LocksI/O operations using [System.Console] are synchronized, which means multiple threads
can read from, or write to, the streams.
Accidental LocksI/O operations using [System.Console] are synchronized, which means multiple threads
can read from, or write to, the streams.
https://github.com/dotnet/corefx/blob/master/src/System.Console/src/System/IO/SyncTextWriter.cs
Introducing…
TPL Dataflow
TPL Dataflow
ActionBlock<T>
TransformBlock<T, U>
TransformManyBlock<T, U>
TPL Dataflow
ActionBlock<T>
TransformBlock<T, U>
TransformManyBlock<T, U>
BatchBlock<T>
JoinBlock<T, U, …>
BatchedJoinBlock<T, U, …>
TPL Dataflow
ActionBlock<T>
TransformBlock<T, U>
TransformManyBlock<T, U>
BufferBlock<T>
WriteOnceBlock<T>
BroadcastBlock<T>
BatchBlock<T>
JoinBlock<T, U, …>
BatchedJoinBlock<T, U, …>
Exec
utio
n
TPL Dataflow
ActionBlock<T>
TransformBlock<T, U>
TransformManyBlock<T, U>
BufferBlock<T>
WriteOnceBlock<T>
BroadcastBlock<T>
BatchBlock<T>
JoinBlock<T, U, …>
BatchedJoinBlock<T, U, …>
Gro
upin
g
Exec
utio
n
TPL Dataflow
ActionBlock<T>
TransformBlock<T, U>
TransformManyBlock<T, U>
BufferBlock<T>
WriteOnceBlock<T>
BroadcastBlock<T>
BatchBlock<T>
JoinBlock<T, U, …>
BatchedJoinBlock<T, U, …>
Buffe
r
Gro
upin
g
Exec
utio
n
TPL Dataflow
ActionBlock<T>
TransformBlock<T, U>
TransformManyBlock<T, U>
BufferBlock<T>
WriteOnceBlock<T>
BroadcastBlock<T>
BatchBlock<T>
JoinBlock<T, U, …>
BatchedJoinBlock<T, U, …>
TPL Dataflow
TPL Dataflow
TPL DataflowBufferBlock<T>
TPL DataflowBufferBlock<T>
TPL Dataflow
BatchBlock<T>
BufferBlock<T>
TPL Dataflow
BatchBlock<T>
BufferBlock<T>
TPL Dataflow
BatchBlock<T>
BufferBlock<T>
TransformManyBlock<T, U>
TPL Dataflow
BatchBlock<T>
BufferBlock<T>
TransformManyBlock<T, U>
TPL Dataflow
BatchBlock<T>
BufferBlock<T>
TransformManyBlock<T, U>
JoinBlock<T, U, …>
TPL Dataflow
BatchBlock<T>
BufferBlock<T>
TransformManyBlock<T, U>
JoinBlock<T, U, …>
TPL Dataflow
BatchBlock<T>
BufferBlock<T>
TransformManyBlock<T, U>
JoinBlock<T, U, …>
ActionBlock<T>
Safe Logger
Safe Logger
• Create interface ILogger
Safe Logger
• Create interface ILogger
• Debug
Safe Logger
• Create interface ILogger
• Debug
• Info
Safe Logger
• Create interface ILogger
• Debug
• Info
• Include / Exclude
Safe Logger
Safe Logger
2015-07-29 18:00:12.565 SimpleLog.iOS [57400:1766661] [2015-07-29T08:00:12.5657180Z] [DBUG00001] [SimpleLog.StartPage.OnSizeAllocated L24]: Size: [568, 288]
Safe Logger
Safe Logger
Safe Logger
• Create LogData class implementing ILogData
Safe Logger
• Create LogData class implementing ILogData
• Use ActionBlock<ILogData>
Safe Logger
• Create LogData class implementing ILogData
• Use ActionBlock<ILogData>
• Profit!
Safe Logger
Safe Logger
Safe Logger
• Test harness for different logging strategies
• Use Scale to increase time spent working vs logging
Safe LoggeriOS Native Console
Blocking √ Scale
Queue √ √Dataflow √ √
Safe Logger
• Android (emulator) very reluctant to race
Safe LoggerAndroid Native Console
Blocking ? ?Queue ? ?
Dataflow ? ?
Safe Logger
• Hardware behaves differently
• Test on real hardware
• Beware memory limitations
DEMO
Safe Logging
Safe Logging• There is no completely safe logging
Safe Logging• There is no completely safe logging
• There's only less dangerous logging
Safe Logging• There is no completely safe logging
• There's only less dangerous logging
• Measuring something changes the way it behaves
Safe Logging• There is no completely safe logging
• There's only less dangerous logging
• Measuring something changes the way it behaves
• Change as little as possible
Safe Logging• There is no completely safe logging
• There's only less dangerous logging
• Measuring something changes the way it behaves
• Change as little as possible
• Especially threads
CAVEAT LOGITOR