Re: performance for high-volume log insertion

On Mon, 20 Apr 2009, Stephen Frost wrote:

> David,
>
> * david(at)lang(dot)hm (david(at)lang(dot)hm) wrote:
>> any idea what sort of difference binary mode would result in?
>
> It depends a great deal on your application..
>
>> currently rsyslog makes use of it's extensive formatting capabilities to
>> format a string along the lines of
>> $DBformat="insert into table X values ('$timestamp','$msg');"
>
> Is this primairly the commands sent to the database? If so, I don't
> think you'll get much by going to binary-mode. The text '$msg' isn't
> going to be any different in binary. The '$timestamp' would be, but I'm
> guessing you'd have to restructure it some to match the PG binary
> timestamp format and while that *would* be a win, I don't think it would
> end up being all that much of a win.

the applicaiton is the log server pulling apart messages, reformatting
them to whatever is appropriate for the database schema, and then
inserting them into the database (for other applications to access, ones
that rsyslog knows nothing about)

I used the example of a trivial table with timestamp and log message, but
in most cases you will break out sending host and application as well, and
in some cases may parse apart the log message itself. I have a use case
where the message itself if pipe delimited, and I will want to do make use
of the first four fields of the message (probably as seperate columns)
before dumping the rest of the message into a text field.

>> I proposed a 5 variable replacement for this to allow for N log entries
>> to be combined into one string to be sent to the database:
>>
>> DBinit (one-time things like initialinzing prepared statements, etc)
>> DBstart (string for the start of a transaction)
>> DBjoin (tring to use to join multiple DBitems togeather)
>> DBend (string for the end of a transaction)
>> DBitem (formatting of a single action )
>>
>> so you could do something like
>>
>> DBstart = "insert into table X values"
>> DBjoin = ","
>> DBend = ";"
>> DBitem = "('$timestampe','$msg')"
>>
>> and it would create a string like #2
>
> Using this textual representation for the DBitem would cause difficulty
> for any kind of prepared statement usage (Oracle or PG), and so I would
> really recommend getting away from it if possible.

that example would be, but the same mechanism would let you do

DBinit="PREPARE rsyslog_insert(date, text) AS\nINSERT INTO foo VALUES(\$1,
\$2);"
DBstart = "begini;B\n"
DBjoin = ""
DBend = "end;"
DBitem = "EXECUTE rsyslog_insert('$timestamp','$msg');\n"

which would become

PREPARE rsyslog_insert(date, text) AS
INSERT INTO foo VALUES($1, $2);
begin;
EXECUTE rsyslog_insert('20090420-06:00', "log1");
EXECUTE rsyslog_insert('20090420-06:00', "log2");
EXECUTE rsyslog_insert('20090420-06:00', "log3");
end;

which I think makes good use of prepared statements.

> Instead, I would
> encourage going with the PG (and Oracle, as I recall) structure of
> having an array of pointers to the values.
>
> Take a look at the documentation for PQexecParams here:
> http://www.postgresql.org/docs/8.3/interactive/libpq-exec.html
>
> (note that you'll want to use PQprepare and PQexecPrepared in the end,
> but the detailed documentation is under PQexecParams)
>
> Basically, you would have:
>
> DBnParams = 2;
> DBparamValues[0] = ptr to $timestamp
> DBparamValues[1] = ptr to $msg
>
> If you just use the text format, you don't actually need anything else
> for PG, just pass in NULL for paramTypes, paramLengths, and
> paramFormats, and 0 for resultFormat.
>
> Of course, if that's your only structure, then you can just make a C
> struct that has those two pointers in it and simplify your API by
> passing the struct around.

the database structure is not being defined by (or specificly for)
rsyslog. so at compile time we have _no_ idea how many variables of what
type there are going to be. my example of ($timestamp,$msg) was intended
to just be a sample (avoiding typing out some elaberate set of parameters)

rsyslog provides the following items, which can be sliced and diced with
substatutions, substrings, and additional inserted text.

msg the MSG part of the message (aka "the message" ;))

rawmsg the message excactly as it was received from the socket. Should be
useful for debugging.

uxtradmsg will disappear soon - do NOT use!

hostname hostname from the message

source alias for HOSTNAME

fromhost hostname of the system the message was received from (in a
relay chain, this is the system immediately in front of us and not
necessarily the original sender). This is a DNS-resolved name, except if
that is not possible or DNS resolution has been disabled.

fromhost-ip The same as fromhost, but alsways as an IP address. Local
inputs (like imklog) use 127.0.0.1 in this property.

syslogtag TAG from the message

programname the "static" part of the tag, as defined by BSD syslogd.
For example, when TAG is "named[12345]", programname is "named".

pri PRI part of the message - undecoded (single value)

pri-text the PRI part of the message in a textual form (e.g.
"syslog.info")

iut the monitorware InfoUnitType - used when talking to a MonitorWare

backend (also for phpLogCon)

syslogfacility the facility from the message - in numerical form

syslogfacility-text the facility from the message - in text form

syslogseverity severity from the message - in numerical form

syslogseverity-text severity from the message - in text form

syslogpriority an alias for syslogseverity - included for historical
reasons (be careful: it still is the severity, not PRI!)

syslogpriority-text an alias for syslogseverity-text

timegenerated timestamp when the message was RECEIVED. Always in high
resolution

timereported timestamp from the message. Resolution depends on what was
provided in the message (in most cases, only seconds)

timestamp alias for timereported

protocol-version The contents of the PROTCOL-VERSION field from
IETF draft draft-ietf-syslog-protcol

structured-data The contents of the STRUCTURED-DATA field from
IETF draft draft-ietf-syslog-protocol

app-name The contents of the APP-NAME field from IETF draft
draft-ietf-syslog-protocol

procid The contents of the PROCID field from IETF draft
draft-ietf-syslog-protocol

msgid The contents of the MSGID field from IETF draft
draft-ietf-syslog-protocol

inputname The name of the input module that generated the message
(e.g. "imuxsock", "imudp"). Note that not all modules necessarily provide
this property. If not provided, it is an empty string. Also note that the
input module may provide any value of its liking. Most importantly, it is
not necessarily the module input name. Internal sources can also provide
inputnames. Currently, "rsyslogd" is defined as inputname for messages
internally generated by rsyslogd, for example startup and shutdown and
error messages. This property is considered useful when trying to filter
messages based on where they originated - e.g. locally generated messages
("rsyslogd", "imuxsock", "imklog") should go to a different place than
messages generated somewhere.

$now The current date stamp in the format YYYY-MM-DD

$year The current year (4-digit)

$month The current month (2-digit)

$day The current day of the month (2-digit)

$hour The current hour in military (24 hour) time (2-digit)

$hhour The current half hour we are in. From minute 0 to 29, this is
always 0 while from 30 to 59 it is always 1.

$qhour The current quarter hour we are in. Much like $HHOUR, but values
range from 0 to 3 (for the four quater hours that are in each hour)

$minute The current minute (2-digit)

$myhostname The name of the current host as it knows itself (probably
useful for filtering in a generic way)

>> this is extremely flexible. I think it can do everything except binary
>> mode operations, including copy. It is also pretty database agnostic.
>
> With that DBitem, I'm not sure how you would do copy easily. You'd have
> to strip out the params and possibly the comma depending on what you're
> doing, and you might have to adjust your escaping (how is that done
> today in $msg?). All-in-all, not using prepared queries is just messy
> and I would recommend avoiding that, regardless of anything else.

rsyslog message formatting provides tools for doing the nessasary escaping
(and is using it for the single insert messages today)

prepared statements in text mode have similar problems (although they
_are_ better in defending against sql injection attacks, so a bit safer).
I don't see how you would easily use the API that you pointed me at above
without having to know the database layout at compile time.

>> but people are asking about how to do binary mode, and some were thinking
>> that you couldn't do prepared statements in Oracle with a string-based
>> interface.
>
> Prepared statements pretty much require that you are able to pass in the
> items in a non-string-based way (I don't mean to imply that you can't
> use *strings*, you can, but it's 1 string per column). Otherwise,
> you've got the whole issue of figuring out where one column ends and the
> next begins again, which is half the point of prepared statements.

if you had said figuring out where the column data ends and the SQL
command begins I would have agreed with you fully.

I agree that defining a fixed table layout and compiling that knowledge
into rsyslog is the safest (and probably most efficiant) way to do things,
but there is no standard for log messages in a database, and different
people will want to do different things with the logs, so I don't see how
a fixed definition could work.

>> so I decided to post here to try and get an idea of (1) how much
>> performance would be lost by sticking with strings, and (2) of all the
>> various ways of inserting the data, what sort of performance differences
>> are we talking about
>
> Sticking with strings, if that's the format that's going to end up in
> the database, is fine. That's an orthogonal issue to using prepared
> statements though, which you should really do. Once you've converted to
> using prepared statements of some kind, and batching together inserts in
> larger transactions instead of one insert per transactions, then you can
> come back to the question of passing things-which-can-be-binary as
> binary (eg, timestamps, integers, floats, doubles, etc) and do some
> performance testing to see how much an improvment it will get you.

so the binary mode only makes a difference on things like timestamps and
numbers? (i.e. no significant added efficiancy in processing the command
itself?)

thanks for taking the time to answer, I was trying to keep the problem
definition small and simple, and from your reply it looks like I made it
too simple.

I think the huge complication is that when RedHat compiles rsyslog to ship
it in the distro, they have no idea how it is going to be used (if it will
go to a database, what database engine it will interface with, or what the
schema of that database would look like). Only the sysadmin(s)/dba(s) know
that and they need to be able to tell rsyslog what to do to get the data
where they want it to be, and in the format they want it to be in.

David Lang