Concurrency mode (#48)

* Initial implementation of concurrency mode.
* Add ability to set each writers concurrency mode individually.
* Adding a mutex around print since we can now be called on multiple threads.
* Removed .swift-version file and moved version into podspec.

Author: tonystone

.swift-version

@@ -4,7 +4,9 @@ All significant changes to this project will be documented in this file.
 ## [4.0.0-beta.1](https://github.com/tonystone/tracelog/tree/4.0.0-beta.1)
 
 #### Added
-- `UnifiedLoggingWriter` for Apple Unified Logging system logging using TraceLog.
+- Added `UnifiedLoggingWriter` for Apple Unified Logging system logging using TraceLog.
+- Added mode to TraceLog.configuration to allow direct, async, or sync mode of operation. Sync & direct mode are useful for use cases that have short-lived processes (scripts) or require real-time logging.
+- Added ability to set the concurrency mode individually for each Writer.
 
 #### Removed
 - Removed all Xcode projects, Xcode projects are now generated using Swift Package Manager.

CHANGELOG.md

@@ -0,0 +1,122 @@
+///
+///  ConcurrencyMode+Extensions.swift
+///
+///  Copyright 2018 Tony Stone
+///
+///  Licensed under the Apache License, Version 2.0 (the "License");
+///  you may not use this file except in compliance with the License.
+///  You may obtain a copy of the License at
+///
+///  http://www.apache.org/licenses/LICENSE-2.0
+///
+///  Unless required by applicable law or agreed to in writing, software
+///  distributed under the License is distributed on an "AS IS" BASIS,
+///  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+///  See the License for the specific language governing permissions and
+///  limitations under the License.
+///
+///  Created by Tony Stone on 5/12/18.
+///
+import Swift
+
+///
+/// The system wide modes that TraceLog can run in.  Used to configure a mode globally at configure time.
+///
+public enum ConcurrencyMode {
+
+    ///
+    /// Direct, as the name implies, will directly call the writer from
+    /// the calling thread with no indirection. It will block until the
+    /// writer(s) in this mode have completed the write to the endpoint.
+    ///
+    /// Useful for scripting applications and other applications where
+    /// it is required for the call not to return until the message is
+    /// printed.
+    ///
+    case direct
+
+    ///
+    /// Synchronous blocking mode is simaler to direct in that it blocks
+    /// but this mode also uses a queue for all writes.  The benifits of
+    /// that is that all threads writing to the log will be serialized
+    /// through before calling the writer (one call to the writer at a
+    /// time).
+    ///
+    case sync
+
+    ///
+    /// Asynchronous non-blocking mode.  A general mode used for most
+    /// application which queues all messages before being evaluated or logged.
+    /// This ensures minimal delays in application execution due to logging.
+    ///
+    case async
+
+    ///
+    /// The default mode used if no mode is specified (.async).
+    ///
+    case `default`
+}
+
+///
+/// Mode to run a specific Writer in. Used to wrap a writer to change the specific mode it operates in.
+///
+public enum WriterConcurrencyMode {
+
+    ///
+    /// Direct, as the name implies, will directly call the writer from
+    /// the calling thread with no indirection. It will block until the
+    /// writer(s) in this mode have completed the write to the endpoint.
+    ///
+    /// Useful for scripting applications and other applications where
+    /// it is required for the call not to return until the message is
+    /// printed.
+    ///
+    case direct(Writer)
+
+    ///
+    /// Synchronous blocking mode is simaler to direct in that it blocks
+    /// but this mode also uses a queue for all writes.  The benifits of
+    /// that is that all threads writing to the log will be serialized
+    /// through before calling the writer (one call to the writer at a
+    /// time).
+    ///
+    case sync(Writer)
+
+    ///
+    /// Asynchronous non-blocking mode.  A general mode used for most
+    /// application which queues all messages before being evaluated or logged.
+    /// This ensures minimal delays in application execution due to logging.
+    ///
+    case async(Writer)
+}
+
+///
+/// Internal ConcurrencyMode extension.
+///
+internal extension ConcurrencyMode {
+
+    ///
+    /// Internal func to convert a `ConcurrencyMode` to a `WriterConcurrencyMode`.
+    ///
+    internal func writerMode(for writer: Writer) -> WriterConcurrencyMode {
+        switch self {
+            case .direct: return .direct(writer)
+            case .sync:   return .sync(writer)
+            default:      return .async(writer)
+        }
+    }
+}
+
+///
+/// Internal WriterConcurrencyMode extension.
+///
+internal extension WriterConcurrencyMode {
+
+    func proxy() -> Writer {
+        switch self {
+            case .direct(let writer):  return writer
+            case .sync(let writer):    return SynchronousWriterProxy(writer: writer)
+            case .async(let writer):   return AsynchronousWriterProxy(writer: writer)
+        }
+    }
+}

Sources/TraceLog/ConcurrencyMode.swift

@@ -19,10 +19,7 @@
 ///
 import Foundation
 
-///
-/// Internal Configuration data
-///
-internal class Configuration {
+extension Configuration {
 
     enum ConfigurationError: Error, CustomStringConvertible {
         case invalidLogLevel(String)
@@ -38,19 +35,29 @@ internal class Configuration {
     private static let logTag    = "LOG_TAG_"
     private static let logPrefix = "LOG_PREFIX_"
     private static let logAll    = "LOG_ALL"
+}
 
-    var globalLogLevel = LogLevel.info
+///
+/// Internal Configuration data
+///
+internal class Configuration {
 
-    var loggedPrefixes: [String: LogLevel] = [:]
-    var loggedTags: [String: LogLevel] = [:]
-    var writers: [Writer]            = [ConsoleWriter()]
+    var globalLogLevel: LogLevel             = .info
+    var loggedPrefixes: [String: LogLevel]   = [:]
+    var loggedTags:     [String: LogLevel]   = [:]
+    var writers:        [Writer]             = []
+    var errors:         [ConfigurationError] = []
 
-    init () {}
+    init(writers: [WriterConcurrencyMode] = [.async(ConsoleWriter())], environment: Environment = Environment()) {
+        self.writers = writers.map( { $0.proxy() } )
+
+        self.errors = self.parse(environment: environment)
+    }
 
     ///
     /// (Re)Load this structure with the values for the environment variables
     ///
-    func load(environment: Environment) -> [ConfigurationError] {
+    private func parse(environment: Environment) -> [ConfigurationError] {
 
         var errors = [ConfigurationError]()
 

Sources/TraceLog/Configuration.swift

@@ -18,7 +18,12 @@
 ///  Created by Tony Stone on 4/23/16.
 ///
 import Foundation
-import Dispatch
+
+#if os(OSX) || os(iOS) || os(watchOS) || os(tvOS)
+    import Darwin
+#elseif os(Linux) || os(FreeBSD) || os(PS4) || os(Android)  /* Swift 5 support: || os(Cygwin) || os(Haiku) */
+    import Glibc
+#endif
 
 ///
 /// ConsoleWriter is the default `Writer` in **TraceLog** and writes to stdout.
@@ -29,10 +34,28 @@ import Dispatch
 ///
 public class ConsoleWriter: Writer {
 
+    ///
+    /// Low level mutex for locking print since it's not reentrent.
+    ///
+    private var mutex = pthread_mutex_t()
+
     ///
     /// Default constructor for this writer
     ///
-    public init() {}
+    public init() {
+        var attributes = pthread_mutexattr_t()
+        guard pthread_mutexattr_init(&attributes) == 0
+            else { fatalError("pthread_mutexattr_init") }
+        pthread_mutexattr_settype(&attributes, Int32(PTHREAD_MUTEX_RECURSIVE))
+
+        guard pthread_mutex_init(&mutex, &attributes) == 0
+            else { fatalError("pthread_mutex_init") }
+        pthread_mutexattr_destroy(&attributes)
+    }
+
+    deinit {
+        pthread_mutex_destroy(&mutex)
+    }
 
     ///
     /// Required log function for the logger
@@ -45,12 +68,21 @@ public class ConsoleWriter: Writer {
         let message         = "\(self.dateFormatter.string(from: date)) \(runtimeContext.processName)[\(runtimeContext.processIdentifier):\(runtimeContext.threadIdentifier)] \(levelString): <\(tag)> \(message)"
 
         ///
-        /// Note: we currently use the calling thread to synchronize knowing that
-        ///       TraceLog calls us in a serial queue.  This can cause interleaving
-        ///       of other message in the output should other threads be used to
-        ///       print to the screen.
+        /// Note: Since we could be called on any thread in TraceLog direct mode
+        /// we protect the print statement with a low-level mutex.
+        ///
+        /// Pthreads mutexes were chosen because out of all the methods of synchronization
+        /// available in swift (queue, dispatch semaphores, etc), pthread mutexes are
+        /// the lowest overhead and fastest lock.
         ///
+        /// We also want to ensure we maintain thread boundaries when in direct mode (avoid
+        /// jumping threads).
+        ///
+        pthread_mutex_lock(&mutex)
+
         print(message)
+
+        pthread_mutex_unlock(&mutex)
     }
 
     ///

Sources/TraceLog/ConsoleWriter.swift

@@ -48,12 +48,12 @@ internal final class Logger {
             self.processName = process.processName
             self.processIdentifier = Int(process.processIdentifier)
 
-            #if os(macOS)
+            #if os(iOS) || os(macOS) || os(watchOS) || os(tvOS)
                 var threadID: UInt64 = 0
 
                 pthread_threadid_np(pthread_self(), &threadID)
                 self.threadIdentifier = threadID
-            #else   // FIXME: Currently it does not seem like Linux supports the pthread_threadid_np method
+            #else   // FIXME: Linux does not support the pthread_threadid_np function, gettid in s syscall must be used.
                 self.threadIdentifier = 0
             #endif
         }
@@ -76,46 +76,25 @@ internal final class Logger {
     }
 
     ///
-    /// Serialization queue for init and writing
+    /// Initialize the config with the default configuration first.  The
+    /// user can re-init this at a later time or simply use the default.
     ///
-    fileprivate static let queue = DispatchQueue(label: "tracelog.write.queue")
-
-    ///
-    /// Initialize the config with the default configuration
-    /// read from the environment first.  The user can re-init
-    /// this at a later time or simply use the default.
-    ///
-    fileprivate static let config = Configuration()
+    fileprivate static var config = Configuration()
 
     ///
     /// Configure the logging system with the specified writers and environment
     ///
-    class func configure(writers: [Writer]? = nil, environment: Environment? = nil) {
-
-        ///
-        /// Note: we use a synchronous call here for the configuration, all
-        ///       other calls must be async in order not to conflict with this one.
-        ///
-        queue.sync {
-
-            if let writers = writers {
-                self.config.writers = writers
-            }
+    class func configure(writers: [WriterConcurrencyMode], environment: Environment) {
 
-            if let environment = environment {
+        self.config = Configuration(writers: writers, environment: environment)
 
-                let errors = config.load(environment: environment)
-
-                logPrimitive(level: .info, tag: moduleLogName, file: #file, function: #function, line: #line) {
-                    "\(moduleLogName) Configured using: \(config.description)"
-                }
-
-                for error in errors {
+        logPrimitive(level: .info, tag: moduleLogName, file: #file, function: #function, line: #line) {
+            "\(moduleLogName) Configured using: \(config.description)"
+        }
 
-                    logPrimitive(level: .warning, tag: moduleLogName, file: #file, function: #function, line: #line) {
-                        "\(error.description)"
-                    }
-                }
+        for error in self.config.errors {
+            logPrimitive(level: .warning, tag: moduleLogName, file: #file, function: #function, line: #line) {
+                "\(error.description)"
             }
         }
     }
@@ -124,25 +103,25 @@ internal final class Logger {
     /// Low level logging function for Swift calls
     ///
     class func logPrimitive(level: LogLevel, tag: String, file: String, function: String, line: Int, message: @escaping () -> String) {
-
-        /// Capture the context outside the dispatch queue
-        let runtimeContext = RuntimeContextImpl()
-        let staticContext  = StaticContextImpl(file: file, function: function, line: line)
-
         ///
-        /// All logPrimitive calls are asynchronous
+        /// Capture the timestamp as early as possible to
+        /// get the most accruate time.
         ///
-        queue.async {
+        let timestamp = Date().timeIntervalSince1970
+
+        /// Copy the config pointer so it does not change while we are using it.
+        let localConfig = self.config
+
+        if localConfig.logLevel(for: tag) >= level {
 
-            if config.logLevel(for: tag) >= level {
-                let timestamp = Date().timeIntervalSince1970
+            let runtimeContext = RuntimeContextImpl()
+            let staticContext  = StaticContextImpl(file: file, function: function, line: line)
 
-                /// Evaluate the message now
-                let messageString = message()
+            /// Evaluate the message now
+            let messageString = message()
 
-                for writer in config.writers {
-                    writer.log(timestamp, level: level, tag: tag, message: messageString, runtimeContext: runtimeContext, staticContext: staticContext)
-                }
+            for writer in localConfig.writers {
+                writer.log(timestamp, level: level, tag: tag, message: messageString, runtimeContext: runtimeContext, staticContext: staticContext)
             }
         }
     }