--debug log messages are now timestamped with fractional seconds.

Messages.hs

@@ -173,7 +173,7 @@ setupConsole :: IO ()
 setupConsole = do
 	s <- setFormatter
 		<$> streamHandler stderr DEBUG
-		<*> pure (simpleLogFormatter "[$time] $msg")
+		<*> pure preciseLogFormatter
 	updateGlobalLogger rootLoggerName (setLevel NOTICE . setHandlers [s])
 	{- This avoids ghc's output layer crashing on
 	 - invalid encoded characters in
@@ -181,6 +181,10 @@ setupConsole = do
 	fileEncoding stdout
 	fileEncoding stderr
 
+{- Log formatter with precision into fractions of a second. -}
+preciseLogFormatter :: LogFormatter a
+preciseLogFormatter = tfLogFormatter "%F %X%Q" "[$time] $msg"
+
 enableDebugOutput :: IO ()
 enableDebugOutput = updateGlobalLogger rootLoggerName $ setLevel DEBUG
 

debian/changelog

@@ -1,3 +1,9 @@
+git-annex (5.20150813) UNRELEASED; urgency=medium
+
+  * --debug log messages are now timestamped with fractional seconds.
+
+ -- Joey Hess <id@joeyh.name>  Wed, 12 Aug 2015 14:31:01 -0400
+
 git-annex (5.20150812) unstable; urgency=medium
 
   * Added support for SHA3 hashed keys (in 8 varieties), when git-annex is

doc/todo/subsecond_timestamping_of_the_--debug_output.mdwn

@@ -1 +1,4 @@
 ATM --debug uses timestamps at second precision.  Would be nice (to see where time is spent) to have subsecond timing
+
+> [[done]], I was able to get fractional seconds down to 0.000001
+> in the debug output. --[[Joey]]

doc/todo/subsecond_timestamping_of_the_--debug_output/comment_1_6067cf9dfbb9dcebfe90951515e2ccdf._comment

@@ -1,8 +0,0 @@
-[[!comment format=mdwn
- username="joey"
- subject="""comment 1"""
- date="2015-08-04T19:32:38Z"
- content="""
-This would require changes to the MissingH library, which is what provides
-the debug logger.
-"""]]