* Marc Alff <marc.alff@stripped> [07/10/18 04:09]:
> Also, it should be noted that the fix is only partial:
> COM_QUERY will log the entire query, without truncation,
> while other places in the code, still calling the general_log_print() method,
> will have a truncated output.
>
> In particular, COM_PREPARE is still truncated (see sql_prepare.cc)
>
> const char *format= "[%lu] %.*b";
> general_log_print(thd, COM_STMT_PREPARE, format, id,
> query_length, query);
While I agree that's it's a nice idea to never truncate anything,
and should perhaps be implemented for general_log_print, I believe
avoiding another copy of the query in case of COM_STMT_PREPARE
should be preferred.
I also habitually joined #support and asked them for alternatives,
and their suggestion was that losing the id in the query hear is
the least possible evil.
This is what I'd suggest to do. (Please update the documentation
too).
17:01 < kostja> we're looking at how to fix 21557
17:01 < kostja> the problem is that currently some queries require formatting...
17:01 < kostja> i.e. in COM_PREPARE:
17:01 < kostja> const char *format= "[%lu] %.*b";
17:01 < kostja> general_log_print(thd, COM_STMT_PREPARE, format, id,
17:01 < kostja> query_length, query);
17:02 < kostja> so .. we either have to make a full copy of the query or truncate it
or remove the formatting.
17:02 < kostja> which option would be best?
17:03 < kostja> I suggest to remove the formatting...
17:03 < kostja> again, the complain is that we truncate queries in the general log.
17:03 < kostja> and we do that because we have to make a copy of the query to
perform this formatting...
17:04 < kostja> Leith, sbester|around roland, Shawn_around, dean, axel, Isotopp,
MLord ^
17:04 < roland> looking kostja
17:05 < kostja> btw, the problem is solved for old way statements.
17:05 < kostja> it's only the prepared statements where we stumbled...
17:05 < dean> kostja: So question is only how to log prepared statements?
17:05 < Leith> remind me exactly what formatting is done?
17:06 < kostja> dean: yes
17:06 < kostja> [%lu] is appended, which is our internal statement id
17:06 < Leith> kostja: remove it then
17:07 < dean> kostja: Remove formatting seems simplest, smallest impact... if there
is a better fix it could happen in some other version
17:07 < roland> kostja: Leith, agree, remove formatting
17:08 < axel> kostja, I'm all for removing the formatting
17:08 < sbester|around> kostja: does that mean we cannot see the statement id in the
logs ?
17:08 < sbester|around> if you remove formatting.
17:08 < kostja> sbester|around: yes. alternatively I could have a separate entry in
the log just to log the statement id.
17:08 < axel> kostja, for PS - how will execute being logged? Will you fill in
current parameters?
17:09 < kostja> axel: yes, _if_ general log is on.
17:09 < kostja> so if you have the logging on, we fill them in.
17:09 < axel> kostja, sbester|around: if execute is logged with values filled in
query string, the statement id is not so important.
17:10 < kostja> axel: still may be useful for debugging ;)
17:10 < kostja> to see the life cycle of a statement.
17:10 < susanne> ?
17:10 < kostja> but I guess this could be done by external tools instead, like proxy
17:10 < axel> otoh it would be nice to identify prepare/execute/reset/close
17:10 < Leith> kostja: can't debug shit if you don't have the full statement :P
17:10 < sbester|around> kostja: i think it's more important to have the entire query
than a truncated query with stmt id... either way, i don't care about general query log
too much ..
17:11 < HarrisonF> morning
17:11 < kostja> HarrisonF: morning
17:11 < Shawn_around> kostja: Our server needs to be debuggable *as is* without
relying on Proxy to pre-process anything.
17:11 < Leith> Hey HarrisonF
17:11 < kostja> Shawn_around: tell me what to do :)
17:11 < axel> susanne, it's about the general log
17:11 < sbester|around> keep the cool formatting and make it unlimited length!!
17:12 < axel> sbester|around, :)
17:12 < sbester|around> there's a mutex ? so printf twice. once for stmtid and again
for query!
17:12 < Shawn_around> kostja: there are two way to log the execution of prepared
statements: 1) reference the prepared statement and list only the parameters or 2)
expand the prepared statement and includ the parameters
17:12 < axel> that means copying the query, allocating a big buffer, overhead etc.
17:12 < Shawn_around> kostja: in either case, we need ALL of the data in the general
query log (no truncation)
17:13 < Leith> let's remember this is a bug fix, and we do not want to change
formatting of a log *too* much in a bug fix
17:13 < roland> kostja: it would be great if you could have an extra column in the
log for statement id.
17:13 < axel> Shawn_around, I guess we all agree on that. Question is: do we need
the statement id?
17:13 < roland> kostja: however
17:13 < roland> kostja: i agree with Leith that the entire statement is more
important to have
17:13 < kostja> I can have two entries in the general log per prepared statement.
17:13 < sbester|around> some users will open a bug report "where are the statement
id's gone!"
17:14 < axel> kostja, if two entries is easier - make it so!
17:14 < kostja> one with the id, another with the query.. They might be separated in
time though, if it's high load
17:14 < kostja> but one will still be able to identify them by connection id...
17:14 < Shawn_around> axel: do we expose that ID anywhere else? Would I be able to
go to the server and say SHOW PREPARED STATEMENTS where ID = 0000 ?
17:14 < roland> kostja: axel: I think that is problemetic,
17:14 < kostja> Shawn_around: no, they are not exposed.
17:14 < roland> kostja: axel: and you still can't see these two belong together
17:14 < axel> Shawn_around, the id is neccessary to identify associated actions.
17:14 < roland> kostja: axel: unless you could guranteed there would be no line
inbetween
17:15 < kostja> i can't.
17:15 < Shawn_around> Then unless there is a running trace in the log where that
same ID value is referenced later, I do not see the value in logging it as the statement
is prepared.
17:15 < kostja> I can make an extra alloc of the query ...
17:15 < roland> kostja: I think you shouldnt do it then
17:15 < kostja> but I am very reluctant to do that...
17:15 < Leith> just blow the id away
17:15 * kostja hates the fact that we already have about 3 copies of the query in the
system...
17:15 < roland> kostja: can you estimate what that would cost?
17:15 < axel> Shawn_around, we want to use the log for tracing sometimes. Or to be
able to say which statement it was that was forgotten to close
17:16 < kostja> what a waste
17:16 < kostja> roland: that would cost nothing for the most common case.
17:16 < kostja> but if you have huge queries...
17:16 < roland> kostja: ok - so you would see more memory consumption? decrease in
response time?
17:16 < kostja> now one needs to think is it likely to have huge queries in
COM_STMT_PREPARE
17:16 < kostja> roland: more mem. consumption.
17:16 < sbester|around> yes
17:17 < Shawn_around> axel: that's great and if we can use the ID to do that, it
would be useful to log it. If we can use the ID to trace executions through the logs,
that would be useful, too.
17:17 < kostja> it's just a discipline we're trying to stick to...
17:17 < sbester|around> up to max_alloweD_apcket
17:17 < axel> kostja, OTOH - the general log *is* expensive. So adding another
malloc() would not be *so* bad.
17:17 < roland> kostja: I still agree with leith that losing the id is the best of
all evil choices
17:17 < axel> roland, ack on that.
17:18 < kostja> ok, I will take that away then.
17:18 < kostja> eof
--
-- Konstantin Osipov Software Developer, Moscow, Russia
-- MySQL AB, www.mysql.com The best DATABASE COMPANY in the GALAXY
