Joshi's Tech Blog

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

noreply@blogger.com (Rohit Joshi) — Thu, 9 Apr 2015 19:24:00 -0400

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)

noreply@blogger.com (Rohit Joshi) — Sun, 29 Mar 2015 16:52:00 -0400



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

noreply@blogger.com (Rohit Joshi) — Tue, 24 Feb 2015 11:53:00 -0500

Comparison between boost lock free and moodycamle queues

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

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

Observations:

For single consumer/single producer: moodycamel::ReaderWriterQueue is faster than boost::lockfree::spsc_queue
For concurrent access, moodycamel::ConcurrentQueue outperforms both boost queue and stack
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

noreply@blogger.com (Rohit Joshi) — Wed, 17 Dec 2014 09:33:00 -0500

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

Nginx: Mutual (Two way) SSL authentication for upstream HTTPS servers

noreply@blogger.com (Rohit Joshi) — Fri, 14 Nov 2014 10:30:00 -0500

Nginx is a really good, high performance reverse proxy server which supports Mutual Authentication for incoming requests but doesn't support for upstream/backend servers. In most of the deployments where nginx is used as a reverse proxy, it also acts as a SSL termination point where upstream requests are routed using either non SSL or one-way SSL connections.

Recently, I was working on a prototype to develop Api Gateway + reverse proxy which manages SSL certificates for different upstream backends and route incoming requests based on the routing rules. Some of the upstream backends expect to have their own certificates with mutual authentication.

After spending sometime on google search and seeing questions posted on stack overflow, I realized that nginx doesn't support mutual/two-way authentications for upstreams so decided to implement support.

I modified ngx_http_proxy_module.c to add following two new config parameters which allows to specify client certificate pem and client certificate key files. I have submitted my patch to nginx development community here.

NOTE: Make sure you do not populate proxy_ssl_trusted_certificate. As it is supported by nginx for upstream one way ssl, it takes preference over my config parameters.

 proxy_ssl_client_certificate  
 proxy_ssl_client_certificate_key

1. Apply below patch to your Nginx source code and recompile. I have verified this patch against nginx-1.4.7
Download patch here.

2. Configure your nginx.conf as below. See the comments for more details.

location /  
      {  
       default_type application/json;  
   
       #this enables client verification  
       proxy_ssl_verify on;  
       proxy_ssl_verify_depth 3;  
   
       #client certificate for upstream server  
       proxy_ssl_client_certificate /etc/upstream-a.pem;  
        
       #client key generated from upstream cert  
       proxy_ssl_client_certificate_key /etc/upstream-a.key;  
        
       #configure based on your security requirement  
       proxy_ssl_ciphers ALL;  
       proxy_ssl_protocols SSLv3 TLSv1 TLSv1.1 TLSv1.2;  
   
       #make sure to match the ssl server name from upstream server certificate   
       proxy_ssl_name "abc.company.com;  
       proxy_pass https://abc.company.com:9900;  
    }

Hope this help. Let me know if you have any questions.

Go vs Rust : Productivity vs Performance

noreply@blogger.com (Rohit Joshi) — Tue, 11 Nov 2014 20:07:00 -0500

Recently, I have been spending some time learning both Go and Rust languages and really excited about these languages evolving differently to solve different problems.

I think Rust will attract developers from C, C++, Fortran and will be used for developing high performance systems like gaming, browsers, telco servers, distributed computing systems as well as low level, cpu efficient embedded/micro computers.

Go seems to be for the Python, Ruby and Java developers and will be used for enterprise applications, mobile apps and application servers.

With my 10+ years of experience in C++ writing applications for telecom service providers where latency and throughput is very important, I really like Rust which simplifies C++ , eliminates memory corruption, improves compile time significantly and being claimed as blazing fast.

Today I came across Computer Language Benchmark comparing Rust and Go from one of the blog I was reading. These are microbenchmark and gives rough idea about how these languages perform for specific algorithm implementation.

Program Source Code	CPU secs	Elapsed secs	Memory KB	Code B	≈ CPU Load
binary-trees
Rust	22.05	5.97	228,196	788	96% 87% 95% 93%
Go	68.41	18.42	266,624	814	94% 94% 92% 93%
pidigits
Rust	1.73	1.73	5,308	1297	1% 100% 0% 0%
Go	3.76	3.52	3,668	674	4% 48% 7% 51%
spectral-norm
Rust	7.87	2.06	5,112	1020	95% 96% 96% 96%
Go	15.70	3.96	1,816	536	99% 99% 99% 99%
reverse-complement
Rust	0.74	0.49	257,160	2015	12% 82% 41% 18%
Go	0.93	0.77	250,564	1243	10% 69% 11% 35%
fasta
Rust	4.99	5.00	4,812	1224	1% 0% 100% 0%
Go	7.26	7.27	1,028	1036	1% 1% 1% 100%
regex-dna
Rust	35.26	11.95	228,296	763	65% 66% 87% 78%
Go	47.40	16.27	543,868	789	86% 64% 64% 78%
fannkuch-redux
Rust	50.01	12.81	7,072	1180	99% 100% 97% 95%
Go	67.16	16.86	1,032	900	100% 100% 100% 100%
mandelbrot
Rust	20.14	5.09	56,824	1290	98% 99% 100% 99%
Go	25.44	6.39	32,276	894	100% 100% 100% 100%
n-body
Rust	20.99	20.99	4,824	1371	1% 0% 0% 100%
Go	22.95	22.95	1,036	1310	0% 0% 100% 1%
k-nucleotide
Rust	26.06	9.76	152,536	2113	42% 83% 43% 99%
Go	30.93	8.42	251,024	1399	98% 91% 90% 90%

To get the comparative data across all these algorithms, I calculated average for combined these algorithms for both the languages.

Results: Average Elapsed seconds and code written for each language:

Language	CPU (Elapsed seconds)	Code (B)
Rust	7.585	1306.1
Go	10.483	959.5

These microbenchmarks shows Rust is ~30+% faster than Go but has ~30+% more code.

Given the computers are getting faster and cheaper but software becoming more complex and maintenance is expensive, I would use Go for an enterprise application.

Which language would you choose and for what kinds of applications?

Fibonacci(50): Rust slower than Go ?

noreply@blogger.com (Rohit Joshi) — Sat, 8 Nov 2014 11:20:00 -0500

I my previous blog post "Fibonnaci (50) : Java > C > C++ > D > Go > Terra (Lua) > LuaJit (Lua) ", I compared language performance using Fibonnaci algorithm where Rust language was not included.

Rust language is being clamined to be "a system programming language that runs blazingly fast, prevents almost all crashes*, and eliminates data races".

I thought of running same fibonnaci algorithm against Rust to see how blazingly fast is it.

You can find fib.rs source code here on lang-compare on my github. I compared it against fib.go and fib.c

FIBONACCI - 50

Language C (gcc-4.9.1):
gcc-4.9 -O3 fib.c
/usr/bin/time -lp ./a.out 50
LANGUAGE C: 12586269025
real 52.87
user 52.83
sys 0.01
557056 maximum resident set size
0 average shared memory size
0 average unshared data size
0 average unshared stack size
163 page reclaims
0 page faults
0 swaps
0 block input operations
0 block output operations
0 messages sent
0 messages received
0 signals received
0 voluntary context switches
497 involuntary context switches

Language Go (go1.4beta1 darwin/amd64):
go build fib.go
/usr/bin/time -lp ./fib 50
LANGUAGE GO: 12586269025
real 96.56
user 96.47
sys 0.06
1232896 maximum resident set size
0 average shared memory size
0 average unshared data size
0 average unshared stack size
300 page reclaims
0 page faults
0 swaps
0 block input operations
0 block output operations
0 messages sent
0 messages received
0 signals received
9010 voluntary context switches
1338 involuntary context switches

Language Rust (0.13.0-nightly (45cbdec41 2014-11-07 00:02:18 +0000)):
/usr/local/bin/rustc --opt-level 3 fib.rs
/usr/bin/time -lp ./fib 50
LANGUAGE Rust: 12586269025
real 101.53
user 101.44
sys 0.01
1040384 maximum resident set size
0 average shared memory size
0 average unshared data size
0 average unshared stack size
229 page reclaims
46 page faults
0 swaps
0 block input operations
0 block output operations
0 messages sent
0 messages received
0 signals received
1 voluntary context switches
914 involuntary context switches

Surprisingly results are as below where CPU usage (real) is as C (52.87) > Go (96.56) > Rust (101.53).

Language	CPU(real)	Memory(Max resident size)
C	52.87	544K
Go	96.56	1204K
Rust	101.53	1016K

NOTE: Is there a better way to read command line argument and convert into integer? I felt it was very painful to figure that out.

E.g.
In C language:
long n = atol(argv[1]);

In Go language:
n, _ := strconv.Atoi(os.Args[1])

In Rust language:
let args = os::args(); let args = args.as_slice(); let n :u64 = from_str::<u64>(args[1].as_slice()).unwrap();

Fibonacci(50) performance : Java > C > C++ > D > Go > Terra (Lua) > Lua-JIT (Lua)

noreply@blogger.com (Rohit Joshi) — Mon, 20 Oct 2014 08:32:00 -0400

Recently, I have been spending some time to learn D and Go languages. D Lang is an evolution of C++ where as Go is being claimed to be an evolution of C but I think it is a Google's attempt to replace dependency on the Java.

I really like the simplicity of Go where the learning curve is very lean but accepting it as a system level programming would be a tough sell. I think it is more for Java/Python developers for building the enterprise softwares rather than using it for hardware/device-drivers/embedded programming, but you never know as Google is very successful selling Android on low powered smart devices.

I did some performance bench for C, C++, D and Go languages using the Fibonacci algorithm.

Results: (see updated results at the end)

For Fibonacci(25), C++ >= Go > C >= Lua-JIT > D > Lua-Terra > Java 1.6

For Fibonacci(50), Java > C > C++ > D-ldc > D-dmd > Go > Lua-Terra > Lua-JIT

Now surprisingly, Java out performed C/C++ for Fibonacci (50) which hurts my ego :) !!

Language	% C++ Speed	Compiler/VM	Flags
FIBONACCI-25
C++	100.0000	Apple LLVM version 6.0	-O3
GO	100.0000	go version go1.3.3 darwin/amd64
C	77.7778	Apple LLVM version 6.0	-O3
LUA	77.7778	LuaJIT 2.0.3
D	63.6364	dmd	-m64 -O -inline -noboundscheck
D	63.6364	ldc	-m64 -O -inline
LUA	43.7500	Terra
JAVA 1.6	43.4783	1.6.0_65-b14-462-11M4609)

FIBONACCI-50
JAVA 1.6	169.6710	1.6.0_65-b14-462-11M4609)
C	101.9846	Apple LLVM version 6.0	-O3
C++	100.0000	Apple LLVM version 6.0	-O3
D	92.6376	ldc	-m64 -O -inline
D	81.7197	dmd	-m64 -O -inline -noboundscheck
GO	76.7760	go version go1.3.3 darwin/amd64
LUA	43.9684	Terra
LUA	38.9649	LuaJIT 2.0.3

For Source code and results: check out my github project.

Update:
It seems Clang on MacOS has some issue. I executed these on my Linux Virtual machine with gnu g++ and g++ is outperforming Java. My ego is intact :)

$g++ --version
g++ (GCC) 4.4.7 20120313 (Red Hat 4.4.7-4)
$g++ -O3 fib.cpp
time ./a.out 50
real 0m47.991s
user 0m47.981s
sys 0m0.000s

$java -version
java version "1.7.0_51"
$javac fib.java
$time java fib 50
real 0m51.897s
user 0m51.815s
sys 0m0.113s

Fibonacci numbers: LuaJIT vs Terra

noreply@blogger.com (Rohit Joshi) — Sun, 19 Oct 2014 21:12:00 -0400

Recently I came across Terra Languange which is a new low-level system programming language that is designed to interoperate seamlessly with the Lua programming language.

I thought of comparing the performance between Lua-Jit and Terra. We all know Lua-JIT is extremely fast thanks to Mike Pall.

You can find fib.lua source code here as lang-compare on my github.

FIBONACCI - 25

>time luajit-2.0.3 fib.lua 25

Running LUA-JIT 2.0.3 test

LANGUAGE LUA: 75025

real 0m0.009s

user 0m0.002s

sys 0m0.006s

Running fib.lua with Terra :

>time terra fib.lua 25

Running Terra test

LANGUAGE LUA: 75025

real 0m0.016s

user 0m0.005s

sys 0m0.010s

Here LuaJIT is 77% faster than Terra for the same fib.lua file.

FIBONACCI - 50

>time luajit-2.0.3 fib.lua 50

Running LUA-JIT test

LANGUAGE LUA: 12586269025

real 3m8.326s

user 3m8.157s

sys 0m0.045s

>time terra fib.lua 50

Running Terra test

LANGUAGE LUA: 12586269025

real 2m46.895s

user 2m46.734s

sys 0m0.043s

Here LuaJit is 56% slower than terra. I ran the same tests multiple times and the results are consistently same where terra is out performing luajit by ~45% when ran for longer duration.

Apple Push Notification Service (APNS) Simulator

noreply@blogger.com (Rohit Joshi) — Thu, 16 Oct 2014 11:28:00 -0400

APNS simulator implementes APNS Specs for a simple and an enhanced push notification.

GitHub: https://github.com/rohitjoshi/apns-sim

Prerequisite:

LuaJit : http://luajit.org/download.html
LuaSec : https://github.com/brunoos/luasec
LuaLogging: http://keplerproject.org/lualogging/
copas: http://keplerproject.github.io/copas/

Once you have downloaded/installed LuaJit and luarocks, other dependencies can be installed using luarocks
e.g.
luarocks install copas

luarocks install LuaSec

luarocks install LuaLogging

Usage:   apns-sim.lua -t ssl_enabled [ -k ssl_key -c ssl_cert] [ -s server -p port -l loglevel -]

Here ssl_key  and ssl_cert fields are mandatory if ssl_enabled is set to true.  

ssl_enabled :  defaul false
server : default value is 127.0.0.1

port  :  default 8080

loglevel : default value is 'warn'

e.g. for ssl connection:
lua  apns-sim.lua -t true -k ./key.pem -c ./cert.pem

for non-ssl connection:  lua  apns-sim.lua

When client connect to this simulator and send a push notification, you will see log entries on console.

Wed Oct 15 09:16:13 2014 INFO Received client connection  from '127.0.0.1:53444':
Wed Oct 15 09:16:13 2014 INFO Received notification: command=1; id=21; expiry=1413382573; token=adf3b210e7adf35f540f45b2697760d9d41081569dc4509ee98bb4d4c92a72ae; payload={"aps":{"alert":{"body":"Hello World"}}}

Improving performance of C# Binding for ZeroMQ (clrzmq)

noreply@blogger.com (Rohit Joshi) — Fri, 4 Jan 2013 11:55:00 -0500

In one of my project, I used ZeroMQ for inter-process communication which is extremely fast, allows async IO, different messaging patterns and supported on multiple platforms/languages.

I used following three messaging patterns.

Publish/Subscribe: Where client subscribes to specific types of messages. When server reads these messages from hardware, it will publish to these clients.
Request/Response: Client can send request to server who execute the request, interact with hardware and get's the response back. E.g Client can request to open a serial port or play an audio.
Push/Pull: All clients will push the logs to the central logging server, central logging server pulls the messages and writes to the file.

As the development is done using C# on Windows Embedded environment, I use clrzmq which is a C# binding for ZeroMQ. Based on my initial performance test, I realized that clrzmq is taking lot more CPU than I expected.

I used RedGate's ANTS performance profiler for .NET which gives detail analysis on how much CPU cycles are spent on each function and how many times it is called.

What I found is that ZmqSocket.Receive() method spent it's time on

SpinWait:17.1%
Stopwatch.GetElapsedDateTimeTicks: 4.1%
Stopwatch.StartNew: 2.4%
Receive: 73.3%

In which Receive() function spent 64.4% of the time on SocketProxy.Receive()

ErrorProxy.get_ShouldTryAgain: 5.1%
SocketProxy.Receive: 64.4%

Now CPU Usage for SocketProxy.Receive()

DisposableIntPtr.Dispose: 11.1%
ZmqMsgT.Init:7.1%
ZmqMsgT.Close:5.8%
SocketProxy.RetryIfInterrupted: 20.8%

See the attached Picture where SocketProxy.Receive() uses 13142.42 CPU ticks
Average CPU ticks per request = 191,196,025 / 14,548 = 13142.42

As part of optimization, I used pre-allocated raw buffer to send and receive data instead of ZmqMsg object, moved StopWatch and SpinWait code in to a limited scope where timeout is defined and longer than certain value.

After these optimization, SocketProxy.Receive() uses only 2696.54 CPU ticks which is almost 1/5 of original cpu usages. See the attached picture below.

Average CPU ticks per request = 5,132,725,522 / 1,903,448 = 2696.54

Here is github link for optimized ZeroMQ library.

I am happy to say that my patch was accepted by clrzmq author and merge into the mainline clrzmq library.

Accessing ZeroMQ from Windows PowerShell

noreply@blogger.com (Rohit Joshi) — Wed, 31 Oct 2012 11:27:00 -0400

In one of the project, we wanted to write logs from Windows PowerShell script to our central logging server when script is executed to update the packages and restart the windows service.

On server side, we implemented ZeroMQ Server (C#) which pulls data from multiple processes and write to the log file using NLog.

On client side, I used Windows PowerShell accessing ZeroMQ push socket to push the messages.

Window PowerShell support loading and accessing functionality from any CLR assemblies.

To load the assembly, you need to use LoadFile function.
[System.Reflection.Assembly]::LoadFile("C:\zmqclr\bin\clrzmq.dll");.

To create the ZeroMQ Context which is a static function,
[ZeroMQ.ZmqContext]::Create()

To create a socket (push) from Zmq Context
([ZeroMQ.ZmqSocket]$zmqCtx.CreateSocket([ZeroMQ.SocketType]::PUSH));

And now connect to the central logging server on port 10000
zmqSocket.Connect("tcp://localhost:10000");

Once Socket is connected, you can send messages using send function.
zmqSocket.Send($data, $data.Length, [ZeroMQ.SocketFlags]::None)

Below is the script.

#=======================================================================
# Purpose: Send logs to logging server using ZeroMQ
# Author: Rohit Joshi
# Date: 10/31/2012
#=======================================================================
#Global variables
$global:zmqSocket=$null
$enc = [system.Text.Encoding]::Unicode

#=======================================================================
# Function: Init ZeroMQ
# Arguments:
#=======================================================================
# Purpose: Initialize the zeromq
#=======================================================================
Function InitZeroMQ()
{

  $zmqCtx= [ZeroMQ.ZmqContext]::Create()
  $global:zmqSocket =([ZeroMQ.ZmqSocket]$zmqCtx.CreateSocket([ZeroMQ.SocketType]::PUSH));
  $global:zmqSocket.SendHighWatermark = 5000;
  $global:zmqSocket.Connect("tcp://localhost:10000");
}

#=======================================================================
# Function: SendMessage
# Arguments: string 
#=======================================================================
# Purpose:Send Message
#=======================================================================
Function SendMessage($msg)
{
 $data=$enc.GetBytes($msg) 
 $global:zmqSocket.Send($data, $data.Length, [ZeroMQ.SocketFlags]::None)
}

InitZeroMQ();
SendMessage("Sending data from PowerShell script");

Map-Reduce implementation in Lua

noreply@blogger.com (Rohit Joshi) — Sun, 9 Sep 2012 12:07:00 -0400

lua-mapreduce is a fast and easy MapReduce implementation for lua inspired by other ma-reduce implementation and particularly octopy in python.

It doesn't aim to meet all your distributed computing needs, but its simple approach is amendable to a large proportion of parallelizable tasks. If your code has a for-loop, there's a good chance that you can make it distributed with just a few small changes.

It uses following lua modules.

lausocket: tcp client-server connectivity
copas: Coroutine Oriented Portable Asynchronous Services for Lua
lualogging
serialize(included in this project)
luafilesystem: Used only in the task-file example to list files from the directory. lua-mapreduce client/server doesn't depend on this module

For windows, you can install luaforwindows which includes these modules.

For Linux/Unix/MacOS and Windows: you can use LuaDist

Directory structure:

lua-mapreduce-server.lua : It is a map-reduce server which receives the connections from clients, sends them task-file and than sends them tasks to perform map/reduce functionality.
lua-mapreduce-client.lua : It connects to the server, receives the task and executes map/reduce functions defines in the task-file
utils/utils.lua : Provides utility functionality
utils/serialize.lua : Provides table serialization functionality
example/word-count-taskfile.lua : Example task-file for counting words from all .lua files in current directory More details on how to create task file is given in word-count example page of wiki.

Usage:

Start Server: lua-mapreduce-server.lua -t task-file.lua [-s server-ip -p port -l loglevel]

2. Start Client: lua-mapreduce-client.lua [-s server-ip -p port -l loglevel]

Creating a task file:

example/word-counttask-file.lua is a sample task-file for work count which implements following functions. Each of these functions are invoked using coroutines to avoid non-blocking calls so as well as returning results one entry at a time to save the memory.

All these functions must be defines as part of table and return this table in function mapreduce()

Server required functions:

taskfn: It reads the source and creates the map of the tasks. E.g For word count, it reads the all file with .lua from current directory and creates a map with key as a file name and content as a value.

    mr.taskfn = function()
        --logger:debug("Getting map task")
        local tasks = read_source()  -- read source is utility function defined to read data source
        for key, value in pairs(tasks) do
            coroutine.yield(key, value)
        end
    end

Here read_source() is a local function defined as below. NOTE: it uses luafilesystem (lfs) module to read the files

    local function read_source()
      --local file_path = system.pathForFile( "*.lua", lfs.currentdir() )
      local file_path = lfs.currentdir()
      --logger:debug("Current directory path:" .. file_path)
      local source_table = {}
      for file in lfs.dir(file_path) do
        if(string.find(file, ".lua") ~= nil) then
        --  logger:debug("File name:" .. file_path .. "/" .. file)
            local c = read_file(file_path .. "/" .. file)
        --  logger:debug("file:" .. file .. ", length:" .. #c)

            if( c ~= nil) then
                source_table[file]=c
            end
        end
      end
      return source_table
    end

finalfn : How to output final result. Here it prints on the console.

mr.finalfn = function (results)
    print("Final results of the task:")
    for key, value in pairs(results) do
        print( key .. ":" .. value)
        coroutine.yield()
    end
end

Client required functions:

mapfn: Map function which processes the task (content of the file here) and splits into lines and each lines into words

-- Map function : Here it splits the content of the files into lines and each line into words
mr.mapfn = function(key, value)
    --logger:debug("mapfn with key:" .. key .. ", value :" .. value .. "\r\n\r\n")
    local file_words = {}

local lines = value:split("[^\r\n%s]+")


--  logger:debug("Number of lines in " .. #lines .. " in the file " .. key)
for k, w in  ipairs(lines) do

    if(w ~= nil) then

        local words = {}
        string.gsub(w, "(%a+)", function (word)
            table.insert(words, string.lower(word))
        end)

        --local words = w:split("[^ %s]+")

        if(words ~= nil) then
            --logger:debug("Number of words in line " .. k .. " are " .. #words)
            for j=1, #words do
                --logger:debug("mapfn:yielding " .. words[j])
                coroutine.yield(words[j], 1)

            end
        end
    end
end


end

reducefn : Reduce function which processes the number of occurrences for a word. Here it returns the size of an array.

    ---Reduce function: It returns the numbe of entries for the values

    mr.reducefn = function (key, value)
        --logger:debug("reducefn: for key:" .. key ..  ", number of words  :" .. #value)
        coroutine.yield(key, #value)
    end

Todo

Add support to handled failed task. currently if client disconnect, the task handled by the client is lost
Support for multiple client connections based on number of cores available on the computer. Use copas for async
Ability to send multiple task-files to the server.
Add more example of task-files
Possibly integrate with apache-mesos

Performance: Nginx, RestExpress, CppCMS, Playframework, Gwan

noreply@blogger.com (Rohit Joshi) — Sat, 7 Apr 2012 05:05:00 -0400

Quick and not-scientific performance test comparison. Goal of this test is to find out how fast is the engine for my car. No car is faster than it's engine capacity. Ofcourse engine is not everything and we can't ride on the engine but it's good to know.

Concurrency Level : 200
Total Request: 100,000
OS: Linux ubuntu 2.6.38-13-generic #57-Ubuntu SMP Mon Mar 5 18:29:54 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

NOTE: I have updated PlayFramework results by using "play start" command as some one mentioned in comment which has improved performance drastically.

Summary:

	Nginx	CppCMS	RestExpress	Play2.0	Gwan
Time taken (sec)	14.17	14.724	19.653	20.896	25.348
Mean request time ms	28.34	29.448	39.448	41.793	50.697
Total requests/sec	7057.28	6791.69	5088.19	4785.52	3945.03
Transfer rate (kb/s)	2494.86	1883.63	1157.76	1065.53	1587.46
Failed Requests	0	0	0	0	2843

With Nginx Frontend	CppCMS	RestExpress	Play2.0
Time taken (sec)	14.672	23.64	26.810
Req per sec (ms)	29.345	47.281	53.621
Reqs per sec	6815.00	4230.05	3729.90
Transfer rate (kb/s)	2076.62	1206.23	1114.60
Failed-Requests	18	0	0

	Nginx	CppCMS	RestExpress	Play2.0	Gwan
CPU%	90	237	254	210	360
Memory (RES)	10088	34m	404m	577m	30m
Memory (SHR)	3424	4444	9996	14m	7704

CppCMS + Nginx front end:
CPU% : 247% ( CppCMS + Nginx)
CPU%: 149% (CppCMS)
Memory (RES) : 17252 (CppCMS + Nginx)
Memory (SHR): 8260 (CppCMS + Nginx)
Memory (RES) : 6700 (CppCMS)
Memory (SHR): 4444 (CppCMS)

1. Nginx (0.8.54)

$ ab -n 100000 -c 200 http://localhost:80/
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software: nginx/0.8.54
Server Hostname: localhost
Server Port: 80

Document Path: /
Document Length: 151 bytes

Concurrency Level: 200
Time taken for tests: 14.170 seconds
Complete requests: 100000
Failed requests: 0
Write errors: 0
Total transferred: 36200000 bytes
HTML transferred: 15100000 bytes
Requests per second: 7057.28 [#/sec] (mean)
Time per request: 28.340 [ms] (mean)
Time per request: 0.142 [ms] (mean, across all concurrent requests)
Transfer rate: 2494.86 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 5 13 6.5 13 141
Processing: 3 15 7.5 14 145
Waiting: 2 11 6.5 10 142
Total: 16 28 9.8 26 157

Percentage of the requests served within a certain time (ms)
50% 26
66% 27
75% 28
80% 28
90% 30
95% 31
98% 56
99% 75
100% 157 (longest request)

top - 05:18:20 up 12:14, 4 users, load average: 1.96, 1.65, 1.38
Tasks: 5 total, 0 running, 5 sleeping, 0 stopped, 0 zombie
Cpu(s): 2.0%us, 16.7%sy, 0.0%ni, 77.2%id, 0.3%wa, 0.0%hi, 3.9%si, 0.0%st
Mem: 4056556k total, 3267276k used, 789280k free, 295200k buffers
Swap: 916476k total, 2732k used, 913744k free, 1360740k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
20974 www-data 20 0 71608 2212 796 S 46 0.1 0:37.47 nginx
20971 www-data 20 0 71608 2212 796 S 17 0.1 0:33.82 nginx
20973 www-data 20 0 71608 2212 796 S 14 0.1 0:31.63 nginx
20972 www-data 20 0 71608 2212 796 S 13 0.1 0:28.03 nginx
20970 root 20 0 71288 1240 240 S 0 0.0 0:00.00 nginx

2. CppCMS (1.0.1)

$ ab -n 100000 -c 200 http://localhost:10000/hello
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software: CppCMS-Embedded/1.0.1
Server Hostname: localhost
Server Port: 10000

Document Path: /hello
Document Length: 147 bytes

Concurrency Level: 200
Time taken for tests: 14.724 seconds
Complete requests: 100000
Failed requests: 0
Write errors: 0
Total transferred: 28400000 bytes
HTML transferred: 14700000 bytes
Requests per second: 6791.69 [#/sec] (mean)
Time per request: 29.448 [ms] (mean)
Time per request: 0.147 [ms] (mean, across all concurrent requests)
Transfer rate: 1883.63 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 8 13 2.0 13 55
Processing: 5 16 2.5 15 57
Waiting: 3 12 2.4 11 51
Total: 17 29 2.9 29 108

Percentage of the requests served within a certain time (ms)
50% 29
66% 29
75% 30
80% 31
90% 32
95% 33
98% 34
99% 35
100% 108 (longest request)

top - 05:14:50 up 12:11, 4 users, load average: 1.84, 1.51, 1.28
Tasks: 2 total, 2 running, 0 sleeping, 0 stopped, 0 zombie
Cpu(s): 4.5%us, 26.5%sy, 0.0%ni, 63.6%id, 0.6%wa, 0.0%hi, 4.8%si, 0.0%st
Mem: 4056556k total, 3186752k used, 869804k free, 295088k buffers
Swap: 916476k total, 2732k used, 913744k free, 1284760k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
21182 rjoshi 20 0 701m 34m 4444 R 237 0.9 12:13.20 hello

3. RestExpress (0.7.1)

Java settings:

/usr/lib/jvm/jdk1.7.0/jre/bin/java -classpath /Downloads/kickstart/build/classes/main:/Downloads/kickstart/lib/DateAdapterJ-1.0.0.jar:/Downloads/kickstart/lib/RestExpress-0.7.1-build-40.jar:/home/rjoshi/Downloads/kickstart/lib/gson-1.6.jar:/Downloads/kickstart/lib/junit-4.4.jar:/home/rjoshi/Downloads/kickstart/lib/netty-3.2.5.Final.jar:/Downloads/kickstart/lib/xpp3_min-1.1.4c.jar:/Downloads/kickstart/lib/xstream-1.3.1.jar com.kickstart.Main

ab -n 100000 -c 200 http://localhost:8081/hello
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software:
Server Hostname: localhost
Server Port: 8081

Document Path: /hello
Document Length: 148 bytes

Concurrency Level: 200
Time taken for tests: 19.653 seconds
Complete requests: 100000
Failed requests: 0
Write errors: 0
Total transferred: 23300000 bytes
HTML transferred: 14800000 bytes
Requests per second: 5088.19 [#/sec] (mean)
Time per request: 39.307 [ms] (mean)
Time per request: 0.197 [ms] (mean, across all concurrent requests)
Transfer rate: 1157.76 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 24 178.9 15 3027
Processing: 1 15 9.4 16 390
Waiting: 1 12 9.2 12 389
Total: 1 39 180.5 31 3326

Percentage of the requests served within a certain time (ms)
50% 31
66% 33
75% 34
80% 35
90% 39
95% 43
98% 45
99% 48
100% 3326 (longest request)

top - 05:31:32 up 12:27, 4 users, load average: 1.92, 1.54, 1.39
Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie
Cpu(s): 5.5%us, 24.0%sy, 0.0%ni, 65.4%id, 0.2%wa, 0.0%hi, 5.0%si, 0.0%st
Mem: 4056556k total, 3748332k used, 308224k free, 297168k buffers
Swap: 916476k total, 2732k used, 913744k free, 1395984k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
10207 rjoshi 20 0 1355m 404m 9996 S 254 10.2 8:51.39 java

4. Playframework (2.0)

Config:
%production.application.mode=prod
logger.root=ERROR
logger.play=ERROR
logger.application=ERROR

Started using: play start

Java settings:

java -Xms512M -Xmx1536M -Xss1M -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=384M -Dfile.encoding=UTF8 -Dplay.version=2.0 -Dsbt.ivy.home=/home/rjoshi/Downloads/play-2.0/framework/../repository -Dplay.home=/home/rjoshi/Downloads/play-2.0/framework -Dsbt.boot.properties=/home/rjoshi/Downloads/play-2.0/framework/sbt/sbt.boot.properties -jar /home/rjoshi/Downloads/play-2.0/framework/sbt/sbt-launch.jar start
rjoshi 3051 2983 99 13:35 pts/0 00:19:59 java -Dsbt.ivy.home=/home/rjoshi/Downloads/play-2.0/framework/../repository -Djava.runtime.name=Java(TM) SE Runtime Environment -Dsun.boot.library.path=/usr/lib/jvm/jdk1.7.0/jre/lib/amd64 -Djava.vm.version=21.0-b17 -Djava.vm.vendor=Oracle Corporation -Djava.vendor.url=http://java.oracle.com/ -Dpath.separator=: -Djava.vm.name=Java HotSpot(TM) 64-Bit Server VM -Dfile.encoding.pkg=sun.io -Duser.country=US -Dsun.java.launcher=SUN_STANDARD -Dsun.os.patch.level=unknown -Djava.vm.specification.name=Java Virtual Machine Specification -Duser.dir=/home/rjoshi/Downloads/play-2.0/samples/java/helloworld -Djava.runtime.version=1.7.0-b147 -Dsbt.boot.properties=/home/rjoshi/Downloads/play-2.0/framework/sbt/sbt.boot.properties -Djava.awt.graphicsenv=sun.awt.X11GraphicsEnvironment -Djava.endorsed.dirs=/usr/lib/jvm/jdk1.7.0/jre/lib/endorsed -Dos.arch=amd64 -Djava.io.tmpdir=/tmp -Dline.separator=? -Djava.vm.specification.vendor=Oracle Corporation -Dos.name=Linux -Dsun.jnu.encoding=UTF-8 -Djava.library.path=:/usr/local/lib:/usr/lib:/usr/share/lib:.:/lib://opt/arawat/lib:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib -Djava.specification.name=Java Platform API Specification -Djava.class.version=51.0 -Dplay.home=/home/rjoshi/Downloads/play-2.0/framework -Dsun.management.compiler=HotSpot 64-Bit Tiered Compilers -Dos.version=2.6.38-13-generic -Duser.home=/home/rjoshi -Duser.timezone=America/New_York -Djava.awt.printerjob=sun.print.PSPrinterJob -Dfile.encoding=UTF8 -Djava.specification.version=1.7 -Djava.class.path=/home/rjoshi/Downloads/play-2.0/framework/sbt/sbt-launch.jar -Duser.name=rjoshi -Dplay.version=2.0 -Djava.vm.specification.version=1.7 -Dsun.java.command=/home/rjoshi/Downloads/play-2.0/framework/sbt/sbt-launch.jar start -Djava.home=/usr/lib/jvm/jdk1.7.0/jre -Dsun.arch.data.model=64 -Duser.language=en -Djava.specification.vendor=Oracle Corporation -Dawt.toolkit=sun.awt.X11.XToolkit -Djava.vm.info=mixed mode -Djava.version=1.7.0 -Djava.ext.dirs=/usr/lib/jvm/jdk1.7.0/jre/lib/ext:/usr/java/packages/lib/ext -Dsun.boot.class.path=/usr/lib/jvm/jdk1.7.0/jre/lib/resources.jar:/usr/lib/jvm/jdk1.7.0/jre/lib/rt.jar:/usr/lib/jvm/jdk1.7.0/jre/lib/sunrsasign.jar:/usr/lib/jvm/jdk1.7.0/jre/lib/jsse.jar:/usr/lib/jvm/jdk1.7.0/jre/lib/jce.jar:/usr/lib/jvm/jdk1.7.0/jre/lib/charsets.jar:/usr/lib/jvm/jdk1.7.0/jre/classes -Djava.vendor=Oracle Corporation -Dfile.separator=/ -Djava.vendor.url.bug=http://bugreport.sun.com/bugreport/ -Dsun.io.unicode.encoding=UnicodeLittle -Dsun.cpu.endian=little -Dsun.desktop=gnome -Dsun.cpu.isalist= -Dhttp.port=9000 -cp /home/rjoshi/Downloads/play-2.0/samples/java/helloworld/target/scala-2.9.1/classes:/home/rjoshi/Downloads/play-2.0/framework/sbt/boot/scala-2.9.1/lib/scala-library.jar:/home/rjoshi/Downloads/play-2.0/repository/local/play/play_2.9.1/2.0/jars/play_2.9.1.jar:/home/rjoshi/Downloads/play-2.0/repository/local/play/templates_2.9.1/2.0/jars/templates_2.9.1.jar:/home/rjoshi/Downloads/play-2.0/repository/local/com.github.scala-incubator.io/scala-io-file_2.9.1/0.2.0/jars/scala-io-file_2.9.1.jar:/home/rjoshi/Downloads/play-2.0/repository/local/com.github.scala-incubator.io/scala-io-core_2.9.1/0.2.0/jars/scala-io-core_2.9.1.jar:/home/rjoshi/Downloads/play-2.0/repository/local/com.github.jsuereth.scala-arm/scala-arm_2.9.1/0.3/jars/scala-arm_2.9.1.jar:/home/rjoshi/Downloads/play-2.0/repository/local/play/anorm_2.9.1/2.0/jars/anorm_2.9.1.jar:/home/rjoshi/Downloads/play-2.0/repository/local/io.netty/netty/3.3.0.Final/bundles/netty.jar:/home/rjoshi/Downloads/play-2.0/repository/local/org.slf4j/slf4j-api/1.6.4/jars/slf4j-api.jar:/home/rjoshi/Downloads/play-2.0/repository/local/org.slf4j/jul-to-slf4j/1.6.4/jars/jul-to-slf4j.jar:/home/rjoshi/Downloads/play-2.0/repository/local/org.slf4j/jcl-over-slf4j/1.6.4/jars/jcl-over-slf4j.jar:/home/rjoshi/Downloads/play-2.0/repository/local/ch.qos.logback/logback-core/1.0.0/jars/logback-core.jar:/home/rjoshi/Downloads/play-2.0/repository/local/ch.qos.logback/logback-classic/1.0.0/jars/logback-classic.jar:/home/rjoshi/Downloads/play-2.0/repository/local/com.typesafe.akka/akka-ac

rjoshi@ubuntu:~$ ab -n 100000 -c 200 http://localhost:9000/
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software:
Server Hostname: localhost
Server Port: 9000

Document Path: /
Document Length: 147 bytes

Concurrency Level: 200
Time taken for tests: 20.896 seconds
Complete requests: 100000
Failed requests: 0
Write errors: 0
Total transferred: 22800000 bytes
HTML transferred: 14700000 bytes
Requests per second: 4785.52 [#/sec] (mean)
Time per request: 41.793 [ms] (mean)
Time per request: 0.209 [ms] (mean, across all concurrent requests)
Transfer rate: 1065.53 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 25 197.9 11 3032
Processing: 3 16 5.5 15 267
Waiting: 2 12 4.8 11 263
Total: 3 40 198.2 26 3060

Percentage of the requests served within a certain time (ms)
50% 26
66% 30
75% 32
80% 33
90% 37
95% 39
98% 44
99% 46
100% 3060 (longest request)

top - 13:44:18 up 22 min, 4 users, load average: 0.41, 0.67, 0.51
Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie
Cpu(s): 20.0%us, 38.3%sy, 0.0%ni, 37.8%id, 0.2%wa, 0.0%hi, 3.7%si, 0.0%st
Mem: 4056556k total, 2775780k used, 1280776k free, 276848k buffers
Swap: 916476k total, 0k used, 916476k free, 933780k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3051 rjoshi 20 0 1527m 408m 12m S 430 10.3 22:16.51 java

5. CppCMS with Nginx frontend

top - 05:52:23 up 12:48, 4 users, load average: 1.60, 1.32, 1.36

Tasks: 6 total, 1 running, 5 sleeping, 0 stopped, 0 zombie

Cpu(s): 5.0%us, 25.8%sy, 0.0%ni, 65.6%id, 0.1%wa, 0.0%hi, 3.5%si, 0.0%st

Mem: 4056556k total, 3281736k used, 774820k free, 298500k buffers

Swap: 916476k total, 2732k used, 913744k free, 1429692k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

10425 rjoshi 20 0 568m 6700 4444 S 149 0.2 1:16.31 hello

10366 www-data 20 0 71608 2308 892 S 37 0.1 0:14.01 nginx

10367 www-data 20 0 71696 2380 892 R 31 0.1 0:15.32 nginx

10368 www-data 20 0 71608 2308 892 S 29 0.1 0:09.18 nginx

10365 www-data 20 0 71608 2312 896 S 1 0.1 0:11.01 nginx

10364 root 20 0 71288 1244 244 S 0 0.0 0:00.00 nginx

$ ab -n 100000 -c 200 http://localhost:9999/hello
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software: nginx/0.8.54
Server Hostname: localhost
Server Port: 9999

Document Path: /hello
Document Length: 147 bytes

Concurrency Level: 200
Time taken for tests: 14.672 seconds
Complete requests: 100000
Failed requests: 18
(Connect: 0, Receive: 0, Length: 18, Exceptions: 0)
Write errors: 0
Non-2xx responses: 18
Total transferred: 31200234 bytes
HTML transferred: 14700468 bytes
Requests per second: 6815.54 [#/sec] (mean)
Time per request: 29.345 [ms] (mean)
Time per request: 0.147 [ms] (mean, across all concurrent requests)
Transfer rate: 2076.62 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 6 12 3.0 12 107
Processing: 3 17 2.8 17 55
Waiting: 3 13 2.7 14 54
Total: 17 29 3.8 29 131

Percentage of the requests served within a certain time (ms)
50% 29
66% 30
75% 31
80% 31
90% 32
95% 33
98% 34
99% 35
100% 131 (longest request)

6. Playframework with Nginx frontend

Configuration:
%production.application.mode=prod
logger.root=ERROR
logger.play=ERROR
logger.application=ERROR

rjoshi@ubuntu:~$ ab -n 100000 -c 200 http://localhost:9999/
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software: nginx/0.8.54
Server Hostname: localhost
Server Port: 9999

Document Path: /
Document Length: 147 bytes

Concurrency Level: 200
Time taken for tests: 26.810 seconds
Complete requests: 100000
Failed requests: 0
Write errors: 0
Total transferred: 30600000 bytes
HTML transferred: 14700000 bytes
Requests per second: 3729.90 [#/sec] (mean)
Time per request: 53.621 [ms] (mean)
Time per request: 0.268 [ms] (mean, across all concurrent requests)
Transfer rate: 1114.60 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 5 53.1 4 3025
Processing: 3 44 297.0 14 3369
Waiting: 3 43 297.0 12 3368
Total: 3 50 301.6 18 3379

Percentage of the requests served within a certain time (ms)
50% 18
66% 22
75% 24
80% 25
90% 29
95% 32
98% 38
99% 284
100% 3379 (longest request)

top - 13:50:05 up 28 min, 5 users, load average: 0.32, 0.32, 0.39
Tasks: 6 total, 2 running, 4 sleeping, 0 stopped, 0 zombie
Cpu(s): 18.7%us, 46.5%sy, 0.0%ni, 27.9%id, 0.0%wa, 0.0%hi, 6.9%si, 0.0%st
Mem: 4056556k total, 2817740k used, 1238816k free, 277404k buffers
Swap: 916476k total, 0k used, 916476k free, 944256k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3051 rjoshi 20 0 1527m 422m 12m S 381 10.7 24:22.37 java
5561 www-data 20 0 72152 2760 796 R 45 0.1 0:06.70 nginx
5559 www-data 20 0 72664 3004 796 S 39 0.1 0:04.60 nginx
5560 www-data 20 0 72636 3244 796 S 28 0.1 0:09.14 nginx
5558 www-data 20 0 71608 2284 864 R 26 0.1 0:07.15 nginx
5557 root 20 0 71288 1248 244 S 0 0.0 0:00.00 nginx

7. RestExpress with Nginx frontend:

$ ab -n 100000 -c 200 http://localhost:9999/hello
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software: nginx/0.8.54
Server Hostname: localhost
Server Port: 9999

Document Path: /hello
Document Length: 148 bytes

Concurrency Level: 200
Time taken for tests: 23.640 seconds
Complete requests: 100000
Failed requests: 0
Write errors: 0
Total transferred: 29200000 bytes
HTML transferred: 14800000 bytes
Requests per second: 4230.05 [#/sec] (mean)
Time per request: 47.281 [ms] (mean)
Time per request: 0.236 [ms] (mean, across all concurrent requests)
Transfer rate: 1206.23 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 6 103.7 1 3014
Processing: 3 36 310.7 13 9320
Waiting: 2 35 310.7 13 9320
Total: 3 42 328.2 16 9320

Percentage of the requests served within a certain time (ms)
50% 16
66% 20
75% 22
80% 24
90% 28
95% 29
98% 31
99% 40
100% 9320 (longest request)

8. GWAN (3.3.28 64-bit (Mar 28 2012 11:24:16))

$ ab -n 100000 -c 200 http://localhost:9090/?hello
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software: G-WAN
Server Hostname: localhost
Server Port: 9090

Document Path: /?hello
Document Length: 146 bytes

Concurrency Level: 200
Time taken for tests: 25.348 seconds
Complete requests: 100000
Failed requests: 2843
(Connect: 0, Receive: 0, Length: 1423, Exceptions: 1420)
Write errors: 0
Total transferred: 41205186 bytes
HTML transferred: 14392242 bytes
Requests per second: 3945.03 [#/sec] (mean)
Time per request: 50.697 [ms] (mean)
Time per request: 0.253 [ms] (mean, across all concurrent requests)
Transfer rate: 1587.46 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 10 25 4.5 25 69
Processing: 6 26 4.8 26 71
Waiting: 0 18 4.6 18 71
Total: 25 50 3.7 50 96

Percentage of the requests served within a certain time (ms)
50% 50
66% 52
75% 52
80% 53
90% 54
95% 56
98% 58
99% 61
100% 96 (longest request)

top - 10:52:11 up 17:48, 4 users, load average: 2.17, 1.53, 1.30
Tasks: 2 total, 0 running, 2 sleeping, 0 stopped, 0 zombie
Cpu(s): 3.0%us, 24.5%sy, 0.0%ni, 64.9%id, 0.2%wa, 0.0%hi, 7.4%si, 0.0%st
Mem: 4056556k total, 3577880k used, 478676k free, 405480k buffers
Swap: 916476k total, 2640k used, 913836k free, 1642436k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
8161 root RT 0 1662m 30m 7704 S 360 0.8 2:06.54 gwan

Installing Android 2.2 on HTC Aria

noreply@blogger.com (Rohit Joshi) — Fri, 8 Oct 2010 14:10:00 -0400

Hi Guys,
I was able to successfully root/jailbreak my HTC Aria phone and install Android 2.2. Here are the steps. (Please try it at your own risk).

Install unrevoked3 to root the phone.
Download CyanogenMod for your version of the handset.
Copy it into your phones SDcard and rename to update.zip
Power off your phone and keep pressing power button (on top) and volume button (on side)
It will reboot with recovery options with multiple menu options.
Select option 6: nandroid to take backup
Select option to 3: "wipe data/factory reset"
Select option 4: "wipe cache partition"
Select option 8: "Advance" and select option "wipe delvik cache".
Selection option "reboot recovery"
Now select option to install update.zip from sdcard.
Reboot the phone and you will have andorid 2.2 install.

Once I installed, everything worked fine except android market place.
13. Enable your wifi internet connection
14. Goto ROM Manager and upgrade FlashClockworkMode version
15. Download market fix to your sd card. Market_fix_bgill55.zip
16. Again follow 5,7,8,9 and 10
17. Go back to ROM manager and select option install from SD card.
18. Select Market_fix_bgill55.zip
19. once installation is done, reboot.

I have no issues so far. Let me know if you find any issue or need help installing it.

boost object pool destroy performance

noreply@blogger.com (Rohit Joshi) — Mon, 17 May 2010 15:41:00 -0400

In one of my application, we wanted to achieve 8000 TPS (Transactions per second) where every second, 8000 session objects will be created and destroyed.
To achieve this performance number, I wanted to optimize memory allocation and deallocation so started looking for existing memory pool class particularly in boost libraries (assuming it would be faster) and I am already using few classes from boost.

I found boost::object_pool. It is a header only file so no need to include link library and I included into my application. At the same time, I used boost::multi_index_container to store session object with multiple indexes. The performance was degrading as number of object increases in the container. I thought that is due to boost multi-index-container.

So I created two separate test applications to measure performance of boost object pool and boost multi-index-container and found that boost object_pool was the bottleneck.

Here is the performance number of destroying 10K, 20K and 30K object from object_pool and using standard c++ delete.

./object_pool_test 10000
Total time to destroy 10000 using delete: 0.3158860
Total time to destroy 10000 from object_pool: 1.447002736 sec

./object_pool_test 20000
Total time to destroy 20000 using delete: 0.6340170
Total time to destroy 20000 from object_pool: 9.624879974 sec

./object_pool_test 30000
Total time to destroy 30000 using delete: 0.10413087
Total time to destroy 30000 from object_pool: 32.150515048 sec

///////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////
// File: test_object_pool.cpp
// Description: Test performance of deleting object from boost::object_pool versus standard delete operator.
// Author: Rohit Joshi
////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////

#include <iostream>
#include <vector>
#include <time.h>
#include <boost/pool/object_pool.hpp>

class Test
{
char buffer[1024];
unsigned long id;
};

int main(int argc, char** argv) {
   if(argc < 2) {
     std::cout << "Usage: "<< argv[0] << " NumObjects\n";
     return 0;
}

int num_objs = atoi(argv[1]);
/////////////////////////////////////////////////////////////////////////////////////////////////
//test1: using standard delete to delete objects
////////////////////////////////////////////////////////////////////////////////////////////////
std::vector<Test*> vDelTest;
vDelTest.reserve(num_objs);
for(int i = 0; i < num_objs; ++i) {
    Test *pTest = new Test();
    vDelTest.push_back(pTest);
}
timespec tv;
tv.tv_sec = 0;
tv.tv_nsec = 0;

clock_settime(CLOCK_PROCESS_CPUTIME_ID, &tv);

for(int i = 0; i < num_objs; ++i) {
    delete vDelTest[i];
}
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &tv);

std::cout << "Total time to destroy "<< num_objs << " using delete: " << tv.tv_sec << "." << tv.tv
_nsec << "\n";

//////////////////////////////////////////////////////////////////////////////////////////////////
//delete using object_pool
/////////////////////////////////////////////////////////////////////////////////////////////////
boost::object_pool<Test> m_oPool;
std::vector<Test*> vTest;
vTest.reserve(num_objs);

for(int i = 0; i < num_objs; ++i) {
    Test *pTest = m_oPool.construct();
    vTest.push_back(pTest);
}

clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &tv);

std::cout << "Total time to destroy "<< num_objs << " from object_pool: " << tv.tv_sec << "." << tv.tv_nsec << "\n";

return 0;

}

To compile, copy this source into test_object_pool.cpp
g++ -c test_object_pool.cpp
g++ -o test_object_pool test_object_pool.o -lrt

Expose stop working after connecting to external monitor

noreply@blogger.com (Rohit Joshi) — Fri, 29 Jan 2010 13:30:00 -0500

When ever I unplug my MacBook from an external monitor, Expose stops working. The solution to this problem is to kill "Dock" application. To make it easier, I have created a script which allows you to do the same.

set app_name to "/System/Library/CoreServices/Dock.app/Contents/MacOS/Dock"
set the_pid to (do shell script "ps ax | grep " & (quoted form of app_name) & " | grep -v grep | awk '{print $1}'")
display dialog "Killingn the application Dock with PID:" & the_pid
if the_pid is not "" then do shell script ("kill -9 " & the_pid)

Copy following lines of code into text editor and copy under $HOME/Library/Scripts/killdock.scpt. Now you can see the script listed under scripts as an shortcut. You can see "kill dock" listed at the end.

Does Internet Speed check varies based on the browser

noreply@blogger.com (Rohit Joshi) — Sun, 10 Jan 2010 12:01:00 -0500

I wanted to see whether browser makes different while checking the speed of the internet. I did speed check test using speedtest.net and four different browser and surprisingly all of them gave different results.

1: Safari Version 4.0.3 (5531.9)
Download Speed: 17.16 Mb/s
Upload speed: 4.08 Mb/s

2. Firefox Version 3.6 (rv:1.9.2 Gecko 20100105)
Download Speed:15.84 Mb/s
Upload Speed:4.25 Mb/s

3. Chrome Version 4.0.246.0 (31780)
Download Speed:15.47 Mb/s
Upload Speed:2.17 Mb/s

4. Chrome Version 4.0.249.43:
Download speed: 17.65 Mb/s
Upload speed: 3.98 Mb/s

Looking at the results, it seems speeds varies based on the browser. You can see latest version of the Google Chrome has improves and you can see both the upload and download speed has increased.

Why google search engine is better than bing for technical information?

noreply@blogger.com (Rohit Joshi) — Fri, 2 Oct 2009 23:09:00 -0400

When Microsoft launched bing search engine, I started using it. I really liked the picture on main page and results are good when I am searching non-technical information. So I changed my default search engine to Bing and set home page as http://www.bing.com.

But when it comes to technical information, bing couldn't provide me information I wanted. It seems it doesn't display the latest information.
E.g I was working on dbxml (Berkeley DB XML) and posted a question to the "dbxml forum". When I searched "dbxml forum" (without quotes), bing fetches following first five search results.

sourceforge.net/projects/dbxml-core
rubyforge.org/forum/?group_id=1643
sourceforge.net/projects/dbxml
dbxml-core.wiki.sourceforge.net/space/stats
eiffel-dbxml.wiki.sourceforge.net

When I search "dbxml forum" (without quotes), it fetches following results.

forums.oracle.com/forums/forum.jspa?forumID=274
www.nabble.com/Berkeley-DB-Xml-f730.html
www.nabble.com/Berkeley-DB-XML-mailing-list-transition-td5475353.html
www.mombu.com/.../t-getting-started-with-berkeley-db-xml-806334.html
www.eosdirectory.com/project/196/Berkeley+DB+XML.html

You can see the difference. The first link is for berkeley db xml forum even though you don't see the dbxml word in the link. Google search engine has latest information about Berkeley DB XML including information that it is bought by Oracle and forums.oracle.com is the latest page for Berkeley DB XML. So every time I search in bing, I had to search it again in google to get the dbxml forum page which was waste of my time. Eventually, I decided had to switch back to google search engine.

Glassfish Application Server Performance tunings

noreply@blogger.com (Rohit Joshi) — Tue, 29 Sep 2009 20:46:00 -0400

If you want to improve performance of your application running on Glassfish application server, you can try out following JVM options. We got significant performance improvement by using them.

<jvm-options>-server</jvm-options>

<jvm-options>-Xms3000m</jvm-options>

<jvm-options>-Xmx3000m</jvm-options>

<jvm-options>-XX:MaxPermSize=192m</jvm-options> 

<jvm-options>-XX:NewRation=2</jvm-options> 

<jvm-options>-XX:+AggressiveHeap</jvm-options>

<jvm-options>-XX:+AggressiveOpts</jvm-options>

<jvm-options>-XX:+UseParallelGC</jvm-options>

<jvm-options>-XX:+UseParallelOldGC</jvm-options>

<jvm-options>-XX:ParallelGCThreads=5</jvm-options>

By using these performance tunings, we are able to get almost 30% more TPS (Transactions per Seconds).If I can be helpful, please do let me know. I have spent enough time on Glassfish and OpenESB performance tunings.

Absolute Singleton. Not Really...

noreply@blogger.com (Rohit Joshi) — Sun, 27 Sep 2009 10:23:00 -0400

Singleton are not true singleton and there are many reasons: One of them is multiple class loaders can have their own copy of singleton. See How single can your singleton instance be?. I started googling for true singleton and came across Absolute Singleton.

When I use this approach in my product, it didn't work instead it was throwing exception java.lang.ClassNotFoundException on the Singleton class.

java.lang.ClassNotFoundException: com.example.common.utils.JCSCache at com.sun.enterprise.util.ConnectorClassLoader.loadClass(ConnectorClassLoader.java:222)
at java.lang.ClassLoader.loadClass(ClassLoader.java:252)
at com.example.common.utils.JCSCache.getInstance(JCSCache.java:131)

After looking at the exception and class initialization, I found that what happens if the first instance is initiated by custom class loader and not the default one?

It will not find an existing instance because while creating the instance, due to custom class loader, it will go into "if (! myClassLoader.toString().startsWith("sun.")) {" (see the Absolute Singleton) condition and try to find existing instance instead of creating new which doesn't exits yet so it throws the java.lang.ClassNotFoundException.

The work around I found is to catch the exception and create the instance of AbsoluteSingleton class.

But next time, custom class loader try to get the instance, again it's not going to find it and create it's own instance.
See the below log.

First instance of JCSCache ( com.example.common.utils.JCSCache@124adaf) created by class loader: org.glassfish.openesb.pojose.jbi.su.SUClassLoader@1b78d60
and

2nd instance (com.example.common.utils.JCSCache@1a859dc) is created by EJBClassLoader.

So Absolute singleton is not really absolute singleton.

[2009-09-27 21:56:04,713 | Thread-79 | common.utils.JCSCache | ENTRY] -->getInstance()
[2009-09-27 21:56:04,713 | Thread-79 | common.utils.JCSCache | DEBUG] Class Loader:org.glassfish.openesb.pojose.jbi.su.SUClassLoader@1b78d60
[2009-09-27 21:56:04,713 | Thread-79 | common.utils.JCSCache | ERROR] Exception:com.example.common.utils.JCSCache
[2009-09-27 21:56:04,713 | Thread-79 | common.utils.JCSCache | ENTRY] -->JCSCache()
[2009-09-27 21:56:04,713 | Thread-79 | common.utils.JCSCache | DEBUG] JCSCache constructor called.
[2009-09-27 21:56:04,713 | Thread-79 | common.utils.JCSCache | EXIT] <--JCSCache() [2009-09-27 21:56:04,713 | Thread-79 | common.utils.JCSCache | ENTRY] -->init()
[2009-09-27 21:56:04,713 | Thread-79 | common.utils.JCSCache | DEBUG] Setting the cache configuratio name:/cache.ccf
[2009-09-27 21:56:04,721 | Thread-79 | common.utils.JCSCache | DEBUG] Initializing region base cache objects.
[2009-09-27 21:56:04,786 | Thread-79 | common.utils.JCSCache | EXIT] <--init() true [2009-09-27 21:56:04,786 | Thread-79 | common.utils.JCSCache | EXIT] <--getInstance() com.example.common.utils.JCSCache@124adaf

2nd instance:

2009-09-27 21:56:06,812 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | ENTRY] -->getInstance()
[2009-09-27 21:56:06,813 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | DEBUG] Class Loader:EJBClassLoader :
[2009-09-27 21:56:06,813 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | ERROR] Exception:com.example.common.utils.JCSCache
[2009-09-27 21:56:06,813 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | ENTRY] -->JCSCache()
[2009-09-27 21:56:06,813 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | DEBUG] JCSCache constructor called.
[2009-09-27 21:56:06,813 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | EXIT] <--JCSCache() [2009-09-27 21:56:06,813 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | ENTRY] -->init()
[2009-09-27 21:56:06,813 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | DEBUG] Setting the cache configuratio name:/cache.ccf
[2009-09-27 21:56:06,818 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | DEBUG] Initializing region base cache objects.
[2009-09-27 21:56:06,926 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | EXIT] <--init() true [2009-09-27 21:56:06,926 | httpSSLWorkerThread-8080-0 | common.utils.JCSCache | EXIT] <--getInstance() com.example.common.utils.JCSCache@1a859dc

How to Enabled logging in OpenLdap

noreply@blogger.com (Rohit Joshi) — Sat, 26 Sep 2009 22:10:00 -0400

I am working on performance improvement task for our new product where I wanted avoid duplicate Ldap seaches. To view the ldap searches in sldap log file, we have to enable the logging. This is how you do it.

To enabled logging:

ldapmodify -x -H ldap://ldaphost -D cn=directory\ manager,cn=config -w password
dn: cn=Config
replace: olcLogLevel
olcLogLevel: Stats Stats2 None
Ctrl+d

Now you can view the log file at /var/log/slapd.log. You will need a root/sudo access to view this log file.

To disabled logging:
ldapmodify -x -H ldap://ldaphost -D cn=directory\ manager,cn=config -w password
dn: cn=Config
replace: olcLogLevel
olcLogLevel: None
Ctrl+d

NOTE: Here is None is used for reporting errors so don't forget to specify None when you enable or disable logging.

If you want to modify existing subscriber data in ldap, you can use this command
ldapmodify -x -H ldap://host -D cn=directory\ manager,o=example.com -w password123 -f modifieddata.ldif

where modifieddata.ldif would contain
dn: uniqueIdentifier=0209091514-1015999999,ou=subscribers,ou=OU,o=example.com
changetype: modify
replace:
:

dn: uniqueIdentifier=0209091514-1016000000,ou=subscribers,ou=OU,o=example.com
changetype: modify
replace:
:

Berkeley DBXML and thread deadlock

noreply@blogger.com (Rohit Joshi) — Wed, 23 Sep 2009 22:46:00 -0400

For my XCAPServer project, I use Berkeley DB XML for XML document repository. I am kind of stuck due to all threads goes into deadlock while adding and removing documents.

See more information on dbxml forum at: DBXML 2.4.16: Accessing containers from multiple threads and deadlock

Solution: To avoid the deadlock, call set_lk_detect(DB_LOCK_MINWRITE) on DbEnv variable. Also make sure when exceptions are thrown, transactions must be either aborted or committed.

Here is a link to the source code: dbxml_db.cpp

XPATH Library performance

noreply@blogger.com (Rohit Joshi) — Tue, 22 Sep 2009 22:20:00 -0400

I am working on a project which requires invoking multiple JBI endpoints based on routing requirements and type of input message. It is developed using heavy xpath expressions to choose the right path in the routing logic.

I started with default XPath library which is part of the JDK 1.6. To avoid the performance problem, I pre-compiled all the xpath expressions at startup time.

When I ran performance test on this router application, I was getting around 670 TPS (transactions per second) with 20% CPU idle (it's a 8 core machine) which is much slower than what I expected.

So I started looking for alternate XPATH libraries and I found VDT-XML benchmark where you can see VDT-XML outperforms jaxen and default jkd xpath implementation.

VDT-XML seem to be much faster (based on benchmark results :) )but due to it's license, I decided not to use for my project so I only option left was to try jaxen xpath library.

When I replaced default xpath library with jaxen, performance numbers changes drastically. Now I get 800 TPS with 70% CPU idle. In-fact I couldn't drive more CPU usage with my jmeter running on one machine.

So I would recommend jaxen library to anyone who is looking high performance, open source/free xpath library.

Boost Logging Library

noreply@blogger.com (Rohit Joshi) — Tue, 22 Sep 2009 22:06:00 -0400

I was evaluating boost log library for my upcoming project XCAPServer. When I googled for boost and logging, I found two boost based logging library.

1. http://torjo.com/log2/doc/html/index.html
2. https://sourceforge.net/projects/boost-log/.

I started with torjo's log library documentation but it looked more complex so I gave up on that.

boost-log library documentation is really good and getting started was much easier so I downloaded the boost-log source and compiled along with my other boost libraries. You can find how to compile boost libraries here.

After spending some time on this library what I realized is that it doesn't support basic logging requirements for my multi-threading application so I had to use C++ macros to achieve what I wanted.

Here is my logger files:
xcap_logger.hpp

xcap_logger.cpp

I just don't understand why logging libraries have to be so complex and still doesn't provide basic logging features e.g file-name, line-number, thread-id etc..we need to learn from java community.

Sometime I feel that boost community should define the interface and let people implement rather than people contributing the implementations and boost community keep on rejecting :)

Here is what I am looking in boost logging library.

My basic requirements for logging libraries are below.

1. Date and Time
2. File Name. Similar to __FILE__ macro
3. Line Number. Similar to __LINE__ macro
4. Current thread id. (pthread_self)
5. Parent thread id. (getpid())
6. Log level (from trace, debug, info, warn, error, critical)
7. Module name
8. Data
e.g
|2009-Sep-22 22:04:47.340047|file.cpp:212|0xb0103000:0xb01020000|INFO|XCAP|test-data