LightQ Performance: transient 1M+ msg/sec, durable 300K+ msg/sec with latency in micro seconds

LightQ is a high performance, brokered messaging queue which supports transient (1M+ msg/sec) and durable (300K+ msg/sec) queues. Durable queues are similar to Kafka where data are written to the file and consumers consume from the file. 
See the blog post for more details.  
For source code, LightIO/LightQ

End to end average latency  is calculated as below.

• Producer sends first message with current timestamp
• Consumer stores this time stamp as a start time
• Consumer stores current time stamp when last message is received.
• Latency = (Consumers's received last message timestamp - Producer's sent first message timestamp)/total messages received

Laptop hardware:

MacBook Pro (Retina, 15-inch, Late 2013)
Processor 2.3 GHz Intel Core i7
Memory 16 GB 1600 MHz DDR3

Broker Type: Transient

Create a transient topic (test), num partition 1

./lightq-topic -n 1
topic test created successfully

100 bytes, 10M messages

Producer: ( 1250000 msg/sec, Bandwidth: 119.2093 MB)

./lightq-producer -m 10000000  -n 1 -s 100
Topic[test_1], Producer: first message sent timestamp [6378502l]
Topic[test_1], Producer: last message sent timestamp [6386647l]
Topic[test_1], Total message sent [10000000] in [8.00] sec
Topic[test_1], Average messages sent per second [1250000.00]
Topic[test_1], Average bandwidth sent per second [119.2093] MB

Consumer: ( 1250000 msg/sec, Latency: 813 ns, Bandwidth: 119.2093 MB)

./lightq-consumer -m 10000000  -n 1
Topic[test_1], First message:  producer start time [6378502], consumer start time [6378520]
Topic[test_1], Total message received [10000000] in [8.00]sec
Topic[test_1], Average messages received per second [1250000.00]
Topic[test_1], Total bytes received [999999907], average bandwidth received per second [119.2093]MB
Topic[test_1], Last Message: consumer endtime [6386632]
Topic[test_1], Consumer first message latency [18] ms
Topic[test_1], Consumer last message received -   producer first message sent timestamp [8130]
Topic[test_1], Average latency [813.00] nano sec

256 bytes, 10M messages

Producer: ( 1250000 msg/sec, Bandwidth: 305.1758 MB)

./lightq-producer -m 10000000  -n 1 -s 256
Topic[test_1], Producer: first message sent timestamp [5826133l]
Topic[test_1], Producer: last message sent timestamp [5834823l]
Topic[test_1], Total message sent [10000000] in [8.00] sec
Topic[test_1], Average messages sent per second [1250000.00]
Topic[test_1], Average bandwidth sent per second [305.1758] MB

Consumer: ( 1250000 msg/sec, Latency: 868 ns, Bandwidth: 305.1758 MB)

./lightq-consumer -m 10000000  -n 1
Topic[test_1], First message:  producer start time [5826133], consumer start time [5826155]
Topic[test_1], Total message received [10000000] in [8.00]sec
Topic[test_1], Average messages received per second [1250000.00]
Topic[test_1], Total bytes received [2559999751], average bandwidth received per second [305.1758]MB
Topic[test_1], Last Message: consumer endtime [5834813]
Topic[test_1], Consumer first message latency [22] ms
Topic[test_1], Consumer last message received - producer first message sent timestamp [8680]
Topic[test_1], Average latency [868.00] nano sec

512 bytes, 10M messages

Producer: ( 1000000 msg/sec, Bandwidth: [488.2812 MB )

./lightq-producer -m 10000000  -n 1 -s 512
Topic[test_1], Producer: first message sent timestamp [6231211l]
Topic[test_1], Producer: last message sent timestamp [6241288l]
Topic[test_1], Total message sent [10000000] in [10.00] sec
Topic[test_1], Average messages sent per second [1000000.00]
Topic[test_1], Average bandwidth sent per second [488.2812] MB

Consumer: ( 1000000 msg/sec, Latency: 1006 ns, Bandwidth: [488.2812 MB )

./lightq-consumer -m 10000000  -n 1
Topic[test_1], First message:  producer start time [6231211], consumer start time [6231235]
Topic[test_1], Total message received [10000000] in [10.00]sec
Topic[test_1], Average messages received per second [1000000.00]
Topic[test_1], Total bytes received [5119999495], average bandwidth received per second [488.2812]MB
Topic[test_1], Last Message: consumer endtime [6241279]
Topic[test_1], Consumer first message latency [24] ms
Topic[test_1], Consumer last message received -   producer first message sent timestamp [10068]
Topic[test_1], Average latency [1006.00] nano sec

1024 bytes, 10M messages

Producer: ( 526315 msg/sec, Bandwidth: 513.9802 MB)

./lightq-producer -m 10000000  -n 1 -s 1024
Topic[test_1], Producer: first message sent timestamp [6029718l]
Topic[test_1], Producer: last message sent timestamp [6049370l]
Topic[test_1], Total message sent [10000000] in [19.00] sec
Topic[test_1], Average messages sent per second [526315.81]
Topic[test_1], Average bandwidth sent per second [513.9802] MB

Consumer: ( 526315 msg/sec, Latency: 1964 ns, Bandwidth: 513.9802 MB)

./lightq-consumer -m 10000000  -n 1
Topic[test_1], First message:  producer start time [6029718], consumer start time [6029727]
Topic[test_1], Total message received [10000000] in [19.00]sec
Topic[test_1], Average messages received per second [526315.81]
Topic[test_1], Total bytes received [10239998983], average bandwidth received per second [513.9802]MB
Topic[test_1], Last Message: consumer endtime [6049366]
Topic[test_1], Consumer first message latency [9] ms
Topic[test_1], Consumer last message received - producer first message sent timestamp [19648]
Topic[test_1], Average latency [1964.00] nano sec

Broker Type: Durable (file)

Create a durable topic (test), num partition 1

./lightq-topic -n 1 -s file
topic test created successfully

100 bytes, 10M messages

Producer: ( 400000 msg/sec, Bandwidth: 38.1470 MB)

./lightq-producer -m 10000000  -s 100 -n 1
Topic[test_1], Producer: first message sent timestamp [4906704l]
Topic[test_1], Producer: last message sent timestamp [4932029l]
Topic[test_1], Total message sent [10000000] in [25.00] sec
Topic[test_1], Average messages sent per second [400000.00]
Topic[test_1], Average bandwidth sent per second [38.1470] MB

Consumer: ( 400000 msg/sec, Latency: 2535 ns, Bandwidth: 38.1470 MB)

./lightq-consumer -c socket -m 10000000 -n 1
Topic[test_1], First message:  producer start time [4906704], consumer start time [4906718]
Topic[test_1], Total message received [10000000] in [25.00]sec
Topic[test_1], Average messages received per second [400000.00]
Topic[test_1], Total bytes received [999999907], average bandwidth received per second [38.1470]MB
Topic[test_1], Last Message: consumer endtime [4932061]
Topic[test_1], Consumer first message latency [14] ms
Topic[test_1], Consumer last message received -   producer first message sent timestamp [25357]
Topic[test_1], Average latency [2535.00] nano sec

256 bytes, 10M messages

Producer: ( 370370 msg/sec, Bandwidth: 90.4224 MB)

./lightq-producer -m 10000000  -s 256 -n 1
Topic[test_1], Producer: first message sent timestamp [4783156l]
Topic[test_1], Producer: last message sent timestamp [4810966l]
Topic[test_1], Total message sent [10000000] in [27.00] sec
Topic[test_1], Average messages sent per second [370370.38]
Topic[test_1], Average bandwidth sent per second [90.4224] MB

Consumer: ( 370370 msg/sec, Latency: 2783 ns, Bandwidth: 90.4224 MB)

./lightq-consumer -c socket -m 10000000 -n 1
Topic[test_1], First message:  producer start time [4783156], consumer start time [4783163]
Topic[test_1], Total message received [10000000] in [27.00]sec
Topic[test_1], Average messages received per second [370370.38]
Topic[test_1], Total bytes received [2559999751], average bandwidth received per second [90.4224]MB
Topic[test_1], Last Message: consumer endtime [4810993]
Topic[test_1], Consumer first message latency [7] ms
Topic[test_1], Consumer last message received -   producer first message sent timestamp [27837]
Topic[test_1], Average latency [2783.00] nano sec

512 bytes, 10M messages

Producer: ( 322580 msg/sec, Bandwidth: 157.5101 MB)

./lightq-producer -m 10000000  -s 512 -n 1
Topic[test_1], Producer: first message sent timestamp [4563339l]
Topic[test_1], Producer: last message sent timestamp [4595009l]
Topic[test_1], Total message sent [10000000] in [31.00] sec
Topic[test_1], Average messages sent per second [322580.66]
Topic[test_1], Average bandwidth sent per second [157.5101] MB

Consumer: ( 322580 msg/sec, Latency: 3168 ns, Bandwidth: 157.5101 MB)

./lightq-consumer -c socket -m 10000000 -n 1
Topic[test_1], First message:  producer start time [4563339], consumer start time [4563361]
Topic[test_1], Total message received [10000000] in [31.00]sec
Topic[test_1], Average messages received per second [322580.66]
Topic[test_1], Total bytes received [5119999495], average bandwidth received per second [157.5101]MB
Topic[test_1], Last Message: consumer endtime [4595027]
Topic[test_1], Consumer first message latency [22] ms
Topic[test_1], Consumer last message received -   producer first message sent timestamp [31688]
Topic[test_1], Average latency [3168.00] nano sec

1024 bytes, 10M messages

Producer: ( 270270 msg/sec, Bandwidth: 263.9358 MB)

./lightq-producer -m 10000000  -s 1024 -n 1
Topic[test_1], Producer: first message sent timestamp [4319543l]
Topic[test_1], Producer: last message sent timestamp [4357308l]
Topic[test_1], Total message sent [10000000] in [37.00] sec
Topic[test_1], Average messages sent per second [270270.28]
Topic[test_1], Average bandwidth sent per second [263.9358] MB

Consumer: ( 270270 msg/sec, Latency: 3779 ns, Bandwidth: 263.9358 MB)

./lightq-consumer -c socket -m 10000000 -n 1
Topic[test_1], First message:  producer start time [4319543], consumer start time [4319564]
Topic[test_1], Total message received [10000000] in [37.00]sec
Topic[test_1], Average messages received per second [270270.28]
Topic[test_1], Total bytes received [10239998983], average bandwidth received per second [263.9358]MB
Topic[test_1], Last Message: consumer endtime [4357340]
Topic[test_1], Consumer first message latency [21] ms
Topic[test_1], Consumer last message received -   producer first message sent timestamp [37797]
Topic[test_1], Average latency [3779.00] nano sec

LightQ : High Performance, brokered messaging queue (transient 1M msg/sec, durable 300K msg/sec)

LightQ is a high performance, brokered messaging queue which supports transient (1M msg/sec) and durable (~300K msg/sec) queues. Durable queues are similar to Kafka where data are written to the file and consumers consume from the file.

Features:

Transient and durable queue (similar to Kafka where producer writes to the file, consumer reads from the file)
Authentication per topic (userid/password validation)
Header only project (embed within your project)
Consumer in load balancing mode(pipeline): One of the consumer gets a message mostly in round robin)
Consumer as Subscribers (Each consumer gets a copy of a message)
Both subscriber and pipelining mode are supported for a single topic
Multi Producers/Consumers for a single topic
Unlimited* topics per broker
JSON protocol to create topic and join topic (at runtime)
C++11 support/require
Logging support
Dynamic port allocation for topic and consumer/producer bind uri
Apache License
Cluster support (todo)
Client API (todo): C, Go, Java, Rust, Lua, Ruby


It is mostly header only project with main.cpp as an example for broker, producer and consumer.

NOTE: This is an initial version and may not be ready for production use.

Protocol:

Create a Topic:

(Admin userid and password must be passed to create a topic. Also we need to define userid/password per topic which consumer/produder need to pass for authentication)
 Send a request  to the broker
{
 "admin_password": "T0p$3cr31",
 "admin_user_id": "lightq_admin",
 "broker_type": "queue",
 "cmd": "create_topic",
 "password": "T0p$3cr31",
 "topic": "test",
 "user_id": "test_admin"
}


Response: 
{
   "cmd": "create_topic",
   "description": "topic created successfully",
   "status": "ok"
}


Join Topic (Consumer):

(Need to pass userid/password for topic 'test')
Request:
{
   "cmd": "join",
   "connection_type": "zmq",
   "password": "T0p$3cr31",
   "topic": "test",
   "type": "pull",
   "user_id": "test_admin"
}
Response: 
{
   "bind_uri": "tcp://127.0.0.1:5002",
   "cmd": "join",
   "status": "ok",
   "topic": "test"
}


Join Topic (Producer):

(Need to pass userid/password for topic 'test')
Request:
{
   "cmd": "join",
   "connection_type": "zmq",
   "password": "T0p$3cr31",
   "topic": "test",
   "type": "pub",
   "user_id": "test_admin"
 }
Response:
{
  "bind_uri": "tcp://127.0.0.1:5003",
  "cmd": "join",
  "status": "ok",
  "topic": "test"
}


Get the statistics about the topic
Request:
{
   "cmd": "stats",
   "password": "T0p$3cr31",
   "topic": "test",
   "user_id": "test_admin"
}
Response:
{
  "cmd": "stats",
  "messages_received": 9499570,
  "messages_sent": 9491554,
  "publishers_count": 1,
  "queue_size": 8016,
  "status": "ok",
  "subscribers_count": 1,
  "total_bytes_read": 0,
  "total_bytes_written": 0


}

Performance:

Laptop hardware:
MacBook Pro (Retina, 15-inch, Late 2013)
Processor 2.3 GHz Intel Core i7
Memory 16 GB 1600 MHz DDR3


Broker Type: Transient

100 bytes, 10M messages

Producer:
./dist/Release/GNU-MacOSX/lightq producer 10000000 100 event
Total Messages:10000000, Time Taken:8.46577 seconds.
Start Time: 1427658489112, End Time:1427658497577
1181227 messages per seconds.
1000000000 bytes sent
112.6507 MB per second


Consumer:
./dist/Release/GNU-MacOSX/lightq consumer queue zmq  pull event
Total Messages:10000001, Time Taken:8.47781 seconds.
Start Time: 1427658489122, End Time:1427658497600
1179550 messages per seconds.
1000000004 bytes received
112.4907 MB per second.


256 bytes 10M Messages

Producer:
./dist/Release/GNU-MacOSX/lightq producer 10000000 256 event
Total Messages:10000000, Time Taken:9.2752 seconds.
Start Time: 1427658738559, End Time:1427658747834
1078143 messages per seconds.
2560000000 bytes sent
263.2186 MB per second.


Consumer:
./dist/Release/GNU-MacOSX/lightq consumer queue zmq  pull event
Total Messages:10000001, Time Taken:9.30292 seconds.
Start Time: 1427658738562, End Time:1427658747865
1074931 messages per seconds.
2560000004 bytes received
262.4345 MB per second.


512 bytes 10M Messages

Producer:
./dist/Release/GNU-MacOSX/lightq producer 10000000 512 event
Total Messages:10000000, Time Taken:10.5182 seconds.
Start Time: 1427658940094, End Time:1427658950612
950734 messages per seconds.
5120000000 bytes sent
464.2258 MB per second.


Consumer:
./dist/Release/GNU-MacOSX/lightq consumer queue zmq  pull event
Total Messages:10000001, Time Taken:10.5296 seconds.
Start Time: 1427658940097, End Time:1427658950627
949706 messages per seconds.
5120000004 bytes received
463.7239 MB per second.


1024 bytes 10M Messages

Producer:
./dist/Release/GNU-MacOSX/lightq producer 10000000 1024 event
Total Messages:10000000, Time Taken:19.8285 seconds.
Start Time: 1427659063592, End Time:1427659083420
504324 messages per seconds.
10240000000 bytes sent
492.5049 MB per second.


Consumer:
./dist/Release/GNU-MacOSX/lightq consumer queue zmq  pull event
Total Messages:10000001, Time Taken:19.8222 seconds.
Start Time: 1427659063603, End Time:1427659083425
504485 messages per seconds.
10240000004 bytes received
492.6617 MB per second.


Performance: (Durable broker: file)

100 bytes, 10M messages

Producer:
./dist/Release/GNU-MacOSX/lightq producer 10000000 100 event
Total Messages:10000000, Time Taken:25.0786 seconds.
Start Time: 1427659575158, End Time:1427659600236
398746 messages per seconds.
1000000000 bytes sent
38.0275 MB per second.


Consumer:
./dist/Release/GNU-MacOSX/lightq consumer file socket  pull event
Total Messages:10000001, Time Taken:25.0945 seconds.
Start Time: 1427659575170, End Time:1427659600264
398493 messages per seconds.
1000000004 bytes received
38.0033 MB per second.


256 bytes 10M Messages

Producer:
./dist/Release/GNU-MacOSX/lightq producer 10000000 256 event
Total Messages:10000000, Time Taken:28.3802 seconds.
Start Time: 1427659339399, End Time:1427659367779
352358 messages per seconds.
2560000000 bytes sent
86.0250 MB per second.


Consumer:
./dist/Release/GNU-MacOSX/lightq consumer file socket  pull event
Total Messages:10000001, Time Taken:28.3939 seconds.
Start Time: 1427659339410, End Time:1427659367804
352188 messages per seconds.
2560000004 bytes received
85.9834 MB per second.


512 bytes 10M Messages

Producer:
./dist/Release/GNU-MacOSX/lightq producer 10000000 512 event
Total Messages:10000000, Time Taken:31.0832 seconds.
Start Time: 1427890737326, End Time:1427890768409
321716 messages per seconds.
5120000000 bytes sent
157.0884 MB per second.


Consumer:
./dist/Release/GNU-MacOSX/lightq consumer file socket  pull event
Total Messages:10000001, Time Taken:31.0935 seconds.
Start Time: 1427890737329, End Time:1427890768423
321610 messages per seconds.
5120000004 bytes received
157.0363 MB per second.


1024 bytes 10M Messages

Producer:
./dist/Release/GNU-MacOSX/lightq producer 10000000 1024 event
Total Messages:10000000, Time Taken:37.4027 seconds.
Start Time: 1427890878446, End Time:1427890915848
267360 messages per seconds.
10240000000 bytes sent
261.0942 MB per second.


Consumer:
./dist/Release/GNU-MacOSX/lightq consumer file socket  pull event
Total Messages:10000001, Time Taken:37.4166 seconds.
Start Time: 1427890878455, End Time:1427890915871
267260 messages per seconds.
10240000004 bytes received
260.9970 MB per second.


Performance Test with 100M  : https://github.com/LightIO/LightQ/blob/master/PerfTest100M.md 

Example: (transient broker)

Start Broker: (broker type: queue, logging level: event)
./dist/Release/GNU-MacOSX/lightq queue event


Start Consumer: (client: consumer, broker type: queue, client socket: zmq, logging level: event)
./dist/Release/GNU-MacOSX/lightq consumer queue zmq  pull event


Start Producer: (client: producer, number of messages 10M, payload size: 100 bytes, logging level: event)
./dist/Release/GNU-MacOSX/lightq producer 10000000 100 event


License :

Source code of LighQ: Apache License

Dependecies:

ZeroMQ LGPL

Queue Benchmark

Comparison between boost lock free and moodycamle queues

Here are comparison between boost lock-free queue and moodycamel queues.

1. Multi Consumers and Multi Producers: boost::lockfree::queue , boost::lockfree::stack, and moodycamel::ConcurrentQueue for concurrent access.
2. Single Consumer and Single Producer: boost::lockfree::spsc_queue and moodycamel::ReaderWriterQueue.

Observations:

1. For single consumer/single producer: moodycamel::ReaderWriterQueue is faster than boost::lockfree::spsc_queue
2. For concurrent access, moodycamel::ConcurrentQueue outperforms both boost queue and stack
3. For some reason, moodycamel::ConcurrentQueue has better performance when 3 or 4 producers/consumers are used than 1 or 2 threads.

boost::lockfree::queue:

boost::lockfree::queue: Producer threads:1, Consumer threads:1, producer_counter: 10000000, consumer_counter 10000000. Time      Taken:2.52799 seconds.
boost::lockfree::queue: Producer threads:2, Consumer threads:2, producer_counter: 10000000, consumer_counter 10000000. Time      Taken:2.63741 seconds.
boost::lockfree::queue: Producer threads:3, Consumer threads:3, producer_counter: 9999999, consumer_counter 9999999. Time        Taken:2.74344 seconds.
boost::lockfree::queue: Producer threads:4, Consumer threads:4, producer_counter: 10000000, consumer_counter 10000000. Time      Taken:2.93172 seconds.

boost::lockfree::stack:

boost::lockfree::stack: Producer threads:1, Consumer threads:1, producer_counter: 10000000, consumer_counter 10000000. Time      Taken:2.22722 seconds.
boost::lockfree::stack: Producer threads:2, Consumer threads:2, producer_counter: 10000000, consumer_counter 10000000. Time      Taken:2.58529 seconds.
boost::lockfree::stack: Producer threads:3, Consumer threads:3, producer_counter: 9999999, consumer_counter 9999999. Time        Taken:2.81599 seconds.
boost::lockfree::stack: Producer threads:4, Consumer threads:4, producer_counter: 10000000, consumer_counter 10000000. Time      Taken:3.22939 seconds.

moodycamel::ConcurrentQueue:

moodycamel::ConcurrentQueue: Producer threads:1, Consumer threads:1, producer_counter: 10000000, consumer_counter 10000000.      Time Taken:1.49435 seconds.
moodycamel::ConcurrentQueue: Producer threads:2, Consumer threads:2, producer_counter: 10000000, consumer_counter 10000000.      Time Taken:1.31297 seconds.
moodycamel::ConcurrentQueue: Producer threads:3, Consumer threads:3, producer_counter: 9999999, consumer_counter 9999999.        Time Taken:0.868555 seconds.
moodycamel::ConcurrentQueue: Producer threads:4, Consumer threads:4, producer_counter: 10000000, consumer_counter 10000000.      Time Taken:0.810693 seconds.

Single Producer / Single Consumer:

boost::lockfree::spsc_queue:

boost::lockfree::spsc_queue: Producer threads:1, Consumer threads:1, producer_counter: 10000000, consumer_counter 10000000. Time Taken:0.776101 seconds.

moodycamel::ReaderWriterQueue:

moodycamel::ReaderWriterQueue: Producer threads:1, Consumer threads:1, producer_counter: 10000000, consumer_counter 10000000. Time Taken:0.586292 seconds.

Rust: Custom Logger with time-stamp, file name and line number

Rust language has a built-in support for logging.  The default logger logs the log level, module name and log message which are not sufficient for troubleshooting. Fortunately,  Rust log crate does allow overriding with a custom logger.

I wanted to log the current time-stamp,  module name, function name and line number and posted a question on Reddit on how do log these information. Based on the answers, Rust does have support for module, line and file name but no support for function name. 

To implement the Custom Logger, I looked at the default logger implementation in  lib.rs in log crate and realized that LogRecord does support file-name and line number but while logging, it does not use it.

 pub fn log(level: u32, loc: &'static LogLocation, args: &fmt::Arguments) {  
    // Test the literal string from args against the current filter, if there  
    // is one.  
    match unsafe { FILTER.as_ref() } {  
      Some(filter) if !filter.is_match(args.to_string().as_slice()) => return,  
      _ => {}  
    }  
    // Completely remove the local logger from TLS in case anyone attempts to  
    // frob the slot while we're doing the logging. This will destroy any logger  
    // set during logging.  
    let mut logger = LOCAL_LOGGER.with(|s| {  
      s.borrow_mut().take()  
    }).unwrap_or_else(|| {  
      box DefaultLogger { handle: io::stderr() } as Box<Logger + Send>  
    });  
    logger.log(&LogRecord {  
      level: LogLevel(level),  
      args: args,  
      file: loc.file,  
      module_path: loc.module_path,  
      line: loc.line,  
    });  
    set_logger(logger);  
  }  

To support the logging of function name, there is a pending RFC/Pull Request, hope that gets implemented before Rust 1.0.

For time being, let manage without function name and implement our custom logger.

 #![feature(phase)]  
 #[phase(plugin, link)]extern crate log;  
 #[phase(plugin, link)]extern crate time;  
 /// import  
 use log::{Logger,LogRecord,LogLevel,LogLocation, set_logger};  
 use std::io::{ LineBufferedWriter, stdio, stderr} ;  
 /// Custom Logger  
 struct CustomLogger {  
    handle: LineBufferedWriter<stdio::StdWriter>,  
  }  
 /// Implements Logger trait for Custom Logger which support logging timestamp, file name and line number  
 /// in addition to log level, module path and message.  
 impl Logger for CustomLogger {  
    fn log(&mut self, record: &LogRecord) {  
      match writeln!(&mut self.handle,  
             "{}:{}:{}:{}:{} {}",  
             time::strftime("%Y-%m-%d %H:%M:%S %Z", &time::now()).unwrap(),  
             record.level,  
             record.module_path,  
             record.file,  
             record.line,  
             record.args) {  
        Err(e) => panic!("failed to log: {}", e),  
        Ok(()) => {}  
      }  
    }  
  }  
 ///main   
 fn main() {  
       log::set_logger(box CustomLogger { handle: stderr() } );  
   debug!("Debug message");  
   warn!("Warn message");  
   error!("Error message");  
 }  

Here is output:

 RUST_LOG=debug ./target/custom-logger  
 2014-12-17 09:23:48 :DEBUG:custom-logger:/projects/rust/custom-logger/src/main.rs:32 Debug message  
 2014-12-17 09:23:48 :WARN:custom-logger:/projects/rust/custom-logger/src/main.rs:33 Warn message  
 2014-12-17 09:23:48 :ERROR:custom-logger:/projects/rust/custom-logger/src/main.rs:34 Error message  

NOTE:  I notice it doesn't print the timezone and leave an empty space.

Once I figure out the timezone issue and logging function name , it will look like below which is much better than file with being repeated.

RUST_LOG=debug ./target/custom-logger  
 2014-12-17 09:23:48 EST:DEBUG:custom-logger::main::32 Debug message  
 2014-12-17 09:23:48 EST:WARN:custom-logger::main:33 Warn message  
 2014-12-17 09:23:48 EST:ERROR:custom-logger::main:34 Error message