Subject: Re: [Sipping] [dispatch] SIP-CLF: Results on ASCII vs. binary representation

From: Theo Zourzouvillys <[email-masked]>
Date: Wed, 29 Apr 2009 16:47:25 +0100

On Wed, Apr 29, 2009 at 3:32 PM, Vijay K. Gurbani
<[email-masked]> wrote:
>  If you find any errors in the programs used to generate
> these results, please do let us know.

actually, your test program is *grossly* skewed in favour of the ASCII
implementation.  If you modify it slightly to behave in a way i'd
expect any developer to, you get (avg 5 runs on a crappy dell vostro
desktop):

 Binary CLF:   0m6.947s
 ASCII CLF:    0m7.004s

If you take i/o out of the question too and set output to /dev/null,
then you get:

 Binary CLF:   0m0.610s
 ASCII CLF:    0m1.905s

which is far more realistic for high throughput servers which are
logging to an in-memory circular buffer or some shared memory
segments.

modified source: http://dev.voip.co.uk/~theo/write-clf.theo.txt
diff: http://dev.voip.co.uk/~theo/write-clf.diff

note that i wrote it in all of about 120 seconds, so there may be some
errors in the output format, but my point stands :-)

 ~ Theo

http://twitter.com/zourzouvillys
http://crazygreek.co.uk/

---

From: "Vijay K. Gurbani" <[email-masked]>
Date: Wed, 29 Apr 2009 09:32:08 -0500

[Bcc'd to sipping]

Hello:

During the SF IETF, the SIP CLF work [2] garnered support
and attention; the minutes of the ad-hoc are archived in [1].

While there was near universal support for having a common
log format, there was a lot of discussion about whether
the format should be text or binary, the argument for binary
being that it should be much faster to search.  An option
for text generation is in [2] and an option for
binary generation is in [3].

We realized the question is not "binary vs. text?" but
"should we optimize for log generation vs. optimize for
log processing?"  To that extent, this email is to socialize
the performance results we have obtained for generating
both binary and ASCII formats, including a simulation of a
worst-case analysis by retrieving the last record from large
binary and ASCII files.

To get these results, we generated 1 Million SIP CLF entries
into an ASCII file and the same 1 Million into a binary file.
The ASCII file followed the convention of [2] and the binary
file that of [3].  The last entry in these files was a SIP
request with a special Call-ID.  We measured the time it took
to search for the special Call-ID in both the binary and ASCII
files.  Here are the results, followed by some discussion; the
source code to the programs that generated these results is
also available (see [4].)

Total records in binary and ASCII CLF file: 1 Million
File size:
   Binary: 300,999,984 bytes
   ASCII:  258,999,984 bytes

Time taken to generate the CLF file with 1 Million records:
   Binary CLF: 138.60s
   ASCII CLF:    7.26s

   This is a difference of almost 20x in favor of the ASCII CLF.

Time taken to seek to the last record of the CLF file:
   Binary CLF:   3.08s
   ASCII CLF:   16.55s (using perl v5.6.1)
                42.92s (using perl v.5.8 and v5.10)

   The ASCII CLF seek is five times slower using perl v5.6.1,
   and 13x slower using perl v5.8 and v5.10.  It looks like later
   versions of perl may have inadvertently made the regex compiler
   less optimized.  We don't know why.

   The above data is from experiments ran on an Intel dual-core
   (T2500 @ 2.00 GHz) IBM T60 laptop running Linux 2.6.27 with 1
   GByte of memory.
   We also ran the programs on a more powerful machine: Intel
   dual-core (X6800 @ 2.93GHz) machines with 8GB RAM and a
   Linux 2.6.24 kernel.  The results scaled accordingly.

Clearly, the biggest difference in the above data is the time
taken to produce the CLF file.  ASCII is a lightweight approach
since the SIP entity producing the ASCII CLF file already has
the SIP message in text form.  It is then just a matter of
writing the fields out on disk.  With the binary form, the
SIP entity producing the binary CLF file has to calculate
offsets, which takes a non-negligible amount of time.  Since
the entity producing the SIP CLF log file should not be over-
burdened with the act of producing it, we feel that ASCII CLF
generation is the only choice here (i.e., we should optimize for
log generation.)  Otherwise, the SIP entity producing the
binary CLF file will spend an inordinate time in calculating
offsets, creating a table of contents, etc. to the detriment
of providing the service it is supposed to.

That said, it is also clear that the the worst-case search
for a record is at five to 13x slower when using ASCII.  But,
because searching is done offline, we feel that this sub-optimality
can well be tolerated.  We also feel that there is value in
specifying a binary format because it allows for SIP operators
who want to do such searches to convert their ASCII files to
binary for optimized traversal and other such uses.  A binary
format  must be defined so that offline processes can convert
the captured ASCII data to binary format for optimized
traversal.

Comments and discussions on these results are welcome.  If
you find any errors in the programs used to generate
these results, please do let us know.

[1] Thread "[Sipping] Meeting Minutes: Ad-hoc Common Log Format
  meeting," IETF SIPPING WG, March 27, 2009.  Archived at:
  http://www.ietf.org/mail-archive/web/sipping/current/msg17199.html

[2] V. Gurbani, E. Burger, T. Anjali, H. Abdelnur and O. Festor,
  "The Common Log File (CLF) format for the Session Initiation
  Protocol (SIP)," IETF Internet-Draft, work in progress, March 9,
  2009.  Archived at:
  http://tools.ietf.org/html/draft-gurbani-sipping-clf-01

[3] A. Roach, "Binary Syntax for SIP Common Log Format," IETF
  Internet-Draft, work in progress, March 25, 2009.  Archived at:
  http://tools.ietf.org/html/draft-roach-sipping-clf-syntax-00.

[4] Source code available at the following URLs; please see
  comment block in clf-write.c on how to generate ASCII and
  binary CLF files.
  http://ect.bell-labs.com/who/vkg/IETF/sip-clf/write-clf.c
  http://ect.bell-labs.com/who/vkg/IETF/sip-clf/clf.h
  http://ect.bell-labs.com/who/vkg/IETF/sip-clf/read-clf-record.c
  http://ect.bell-labs.com/who/vkg/IETF/sip-clf/read-clf-record.pl
  http://ect.bell-labs.com/who/vkg/IETF/sip-clf/Makefile

Thanks,

- vijay
-- 
Vijay K. Gurbani, Bell Laboratories, Alcatel-Lucent
1960 Lucent Lane, Rm. 9C-533, Naperville, Illinois 60566 (USA)
Email: vkg@{alcatel-lucent.com,bell-labs.com,acm.org}
Web:   http://ect.bell-labs.com/who/vkg/

---

From: "Vijay K. Gurbani" <[email-masked]>
Date: Wed, 29 Apr 2009 13:12:28 -0500

> expect any developer to, you get (avg 5 runs on a crappy dell vostro
[...]

Theo: True, using scatter-gather (s-g) writes you can optimize the
binary I/O.

By the same token, I can optimize the ASCII writes a bit using
s-g writes; for instance, I was able to bring the average down
by 1.02s for ASCII CLF using s-g writes.

But we intentionally stayed away from s-g writes for the
following four reasons:

1) On some systems, the value of IOV_MAX is set to a low number.
   For example, in Solaris 8 the value of IOV_MAX is set to 16,
   forcing you to do multiple s-g I/O calls (thereby negating
   some of the optimization effects.)

2) Some systems have a maximum ceiling on how many bytes can
   be transferred in one writev(), i.e., the sum of all iov_len
   members of the iov array should be less than a certain
   system-defined maximum.

     [Note: I seem to remember that a few years ago, the
     Apache lists were full of problems related to 1 and 2.]

3) Portability: I was not sure how portable the writev() system
   call would be on all kinds of operating environments.  Since
   the SIP CLF is designed for all SIP entities, if a (real-time)
   operating system does not have the writev() system call, one
   is forced to used the non-optimized method anyway.  Furthermore,
   in a RT OS, the limits for 1 and 2 will be much lower, if
   writev() is provided at all.

4) We did not necessarily want to make any assumptions about
   how implementations have created data structures to hold
   the results of parsing (i.e., some implementations may very
   well use struct's to store the text and length for each
   SIP token, while others may simply store the text and
   compute the length when needed, etc.)  For the sake of
   demonstration, our program implements the first option
   (i.e., uses struct's to store the text and length), which
   is actually more conducive to the s-g approach, but by no
   means is this the only way to design your data structures.

(1) is a real concern because as you can well imagine that URIs,
once parsed, can be composed of many different objects (or
structs in C.)  As such, the representation of a composed URI
in a iov structure will require multiple indexes.

Hence, we wanted to use the most common denominator to do the
measurements -- in our initial performance data, there is no
optimization for either the binary CLF case or the ASCII CLF case.

> errors in the output format, but my point stands :-)

There appear to be since I cannot read the last record; but I
have not had the chance to look at the output format from your
program in any detail.

Thanks,

- vijay

---

From: "Mary Barnes" <[email-masked]>
Date: Wed, 29 Apr 2009 13:14:47 -0500

Folks,

Please direct any comments to the DISPATCH WG mailing list.

Thanks,
Mary. 

-----Original Message-----
From: [email-masked] [mailto:[email-masked]] On
Behalf Of Vijay K. Gurbani
Sent: Wednesday, April 29, 2009 9:32 AM
To: [email-masked]; [email-masked]
Subject: [Sipping] SIP-CLF: Results on ASCII vs. binary representation

[Bcc'd to sipping]

Hello:

During the SF IETF, the SIP CLF work [2] garnered support and attention;
the minutes of the ad-hoc are archived in [1].

While there was near universal support for having a common log format,
there was a lot of discussion about whether the format should be text or
binary, the argument for binary being that it should be much faster to
search.  An option for text generation is in [2] and an option for
binary generation is in [3].

We realized the question is not "binary vs. text?" but "should we
optimize for log generation vs. optimize for log processing?"  To that
extent, this email is to socialize the performance results we have
obtained for generating both binary and ASCII formats, including a
simulation of a worst-case analysis by retrieving the last record from
large binary and ASCII files.

To get these results, we generated 1 Million SIP CLF entries into an
ASCII file and the same 1 Million into a binary file.
The ASCII file followed the convention of [2] and the binary file that
of [3].  The last entry in these files was a SIP request with a special
Call-ID.  We measured the time it took to search for the special Call-ID
in both the binary and ASCII files.  Here are the results, followed by
some discussion; the source code to the programs that generated these
results is also available (see [4].)

Total records in binary and ASCII CLF file: 1 Million File size:
   Binary: 300,999,984 bytes
   ASCII:  258,999,984 bytes

Clearly, the biggest difference in the above data is the time taken to
produce the CLF file.  ASCII is a lightweight approach since the SIP
entity producing the ASCII CLF file already has the SIP message in text
form.  It is then just a matter of writing the fields out on disk.  With
the binary form, the SIP entity producing the binary CLF file has to
calculate offsets, which takes a non-negligible amount of time.  Since
the entity producing the SIP CLF log file should not be over- burdened
with the act of producing it, we feel that ASCII CLF generation is the
only choice here (i.e., we should optimize for log generation.)
Otherwise, the SIP entity producing the binary CLF file will spend an
inordinate time in calculating offsets, creating a table of contents,
etc. to the detriment of providing the service it is supposed to.

That said, it is also clear that the the worst-case search for a record
is at five to 13x slower when using ASCII.  But, because searching is
done offline, we feel that this sub-optimality can well be tolerated.
We also feel that there is value in specifying a binary format because
it allows for SIP operators who want to do such searches to convert
their ASCII files to binary for optimized traversal and other such uses.
A binary format  must be defined so that offline processes can convert
the captured ASCII data to binary format for optimized traversal.

Comments and discussions on these results are welcome.  If you find any
errors in the programs used to generate these results, please do let us
know.

Thanks,

- vijay
--
Vijay K. Gurbani, Bell Laboratories, Alcatel-Lucent 1960 Lucent Lane,
Rm. 9C-533, Naperville, Illinois 60566 (USA)
Email: vkg@{alcatel-lucent.com,bell-labs.com,acm.org}
Web:   http://ect.bell-labs.com/who/vkg/
_______________________________________________
Sipping mailing list  https://www.ietf.org/mailman/listinfo/sipping
This list is for NEW development of the application of SIP Use
[email-masked] for questions on current sip Use
[email-masked] for new developments of core SIP

---

From: Theo Zourzouvillys <[email-masked]>
Date: Wed, 29 Apr 2009 20:03:02 +0100

> 1) On some systems, the value of IOV_MAX is set to a low number.

(1) is irrelivant.  scatther/gather is not the only optimal method of
implementing it.  even on crappy old OSes, a simple memcpy() of the
data is similar in performance, cache coherency caveat emptor:

  http://dev.voip.co.uk/~theo/write-clf.theo2.txt

Binary: 0m7.400s
ASCII: 0m7.038s

> in a iov structure will require multiple indexes.

i'd argue your concerns are moot - a URI composed of many different
objects will need to be built into a string if it's ASCII anyway.

to be honest, i through they took the performance card out of the pack
so it couldn't be used any more in 2002 - if logging is causing you
scalability problems, you've got far more to worry about than that.
plus, any implementation not running on a modern OS is going to have
other missing features needed for performance improvements outside of
writev()'s limitations

(ps: i'm not too concerned about binary/ascii - although i lean toward
the binary side - please just don't use performance as an argument
unless the figures are fair. pretty please!)

 ~ Theo