Skip site navigation (1) Skip section navigation (2)

Re: performance for high-volume log insertion

From: david(at)lang(dot)hm
To: Stephen Frost <sfrost(at)snowman(dot)net>
Cc: pgsql-performance(at)postgresql(dot)org
Subject: Re: performance for high-volume log insertion
Date: 2009-04-21 03:29:54
Message-ID: alpine.DEB.1.10.0904201959210.12662@asgard.lang.hm (view raw or flat)
Thread:
Lists: pgsql-performance
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

In response to

Responses

pgsql-performance by date

Next:From: Stephen FrostDate: 2009-04-21 04:10:08
Subject: Re: performance for high-volume log insertion
Previous:From: Stephen FrostDate: 2009-04-21 03:15:18
Subject: Re: performance for high-volume log insertion

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group