RE: libpq debug log
Hi, Thank you for your comments and advice. I'd like to consider your suggestions. I am planning to change libpq logging like this; 1. Expand PQtrace() facility and improve libpq logging. 2. Prepare "output level". There are 3 type of levels; - TRADITIONAL : if set, outputs protocol messages - LEVEL1: if set, outputs phase and time - LEVEL2: if set, outputs both info TRADITIONAL and LEVEL1 3. Add "output phase" information; This is the processing flow. (ex. When PQexec() start and end ) 4. Change output method to callback style; Default is stdout, and prepare other callback functions that will be used more frequently. 5. Initialization method; In current one: PQtrace(PGconn *conn, FILE *stream); Proposed change: PQtraceEx(PGconn *conn, FILE *stream, PQloggingProcessor callback_func , void *callback_arg, PGLogminlevel level); PQtrace() can be use as it is to consider compatibility with previous applications, so I leave PQtrace() and created a new function PQtraceEx(). After discussing the abovementioned, then maybe we can discuss more about enabling trace output and changing the output style. What do you think? I would appreciate your comments and suggestions. Regards, Aya Iwata
RE: libpq debug log
Hi Horiguchi-san, Thank you for your reply and suggestions. > > 1. Expand PQtrace() facility and improve libpq logging. > > > > 2. Prepare "output level". There are 3 type of levels; > > - TRADITIONAL : if set, outputs protocol messages > > - LEVEL1: if set, outputs phase and time > > - LEVEL2: if set, outputs both info TRADITIONAL and > > LEVEL1 > > You appear to want to segregate the "traditional" output from what you want > to emit. At least Tom is explicitly suggesting to throw away the hypothtical > use cases for it. You may sort out what kind of information you/we want to > emit as log messages from scratch:p > > You may organize log kinds into hierachical levels like server log messages > or into orthogonal types that are individually turned on. But it is not > necessarily be a parameter of a logging processor. (mentioned below) It is intended for old application users who use PQtrace() expect the existing/default/traditional log output style. That’s why I separated other information(ex. phase and timestamp). But since you mentioned the level is not necessary, I will follow your advice and include those information in the reformatted PQtrace(). > > 3. Add "output phase" information; This is the processing flow. (ex. > > When PQexec() start and end ) > > What is the advantage of it against just two independent messages like > PQexec_start and PQexec_end? (I don't see any advantage.) I think the purpose of this logging improvement is to make it useful for analysis at performance deterioration. When query delay happens, we want to know from which side(server or client) is the cause of it, and then people want to know which process takes time. I think the phase and time information are useful for diagnosis. For example, when command processing function (ex. PQexec()) etc. start/end and when client receive/send protocol messages. /*my intended output here */ > > 4. Change output method to callback style; Default is stdout, and prepare > other callback functions that will be used more frequently. > > Are you going to make something less-used the default behavior? I think no > one is opposing rich functionality as far as it is replaceable. I am sorry, my explanation was not clear. I just wanted to say I intend to provide several output method functions which users likely need. ex. output to stdout, or output to file, or output to log directory. > > 5. Initialization method; > > In current one: PQtrace(PGconn *conn, FILE *stream); Proposed change: > > PQtraceEx(PGconn *conn, FILE *stream, PQloggingProcessor callback_func > > , void *callback_arg, PGLogminlevel level); > > I'm not sure we should add a new *EX() function. Couldn't we just change the > signature of PQtrace()? I intended to add new *EX() function for compatibility purposes specially for old version of libpq. I would like to avoid making changes to old applications for this. But if we insist on changing the PQtrace() itself, then I will follow your advice. > > callback_funs seems to be a single function. I think it's better to have > individual function for each message type. Not > callback_func(PQLOG_EXEC_START, param_1, param_2,...) ,but > PQloggingProcessor.PQexec_start(param_1, param_2, ...). > > It is because the caller can simply pass values in its own type to the > function > without casting or other transformations and their types are checked > statically. > > I also think it's better that logger-specific paramters are not passed in > this level. Maybe stream and level are logger-specific paratmer, which can > be combined into callback_arg, or can be given via an API function. Thank you for your advice. I will consider it. Regards, Aya Iwata
RE: libpq debug log
Hi everyone, I appreciate all the helpful advice. I agree to display message more clearly. I will follow your advice. I would like to add timestamp per line and when command processing function start/end. I think it is useful to know the application process start/end for diagnosis. So I will implement like this; 2019-03-03 07:24:54.142 UTC PQgetResult start 2019-03-03 07:24:54.143 UTC < 'T' 35 1 "set_config" 0 #0 25 #65535 -1 #0 2019-03-03 07:24:54.144 UTC PQgetResult end > > But I still don't really see a need for different levels or whatever. > > I mean, you either want a dump of all of the protocol traffic, or you > > don't, I think. Or maybe I am confused as to what the goal of all > > this really is. > > Yeah, me too. But a lot of this detail would only be useful if you were > trying > to diagnose something like a discrepancy between the server and libpq as to > the width of some field. And the number of users for that can be counted > without running out of fingers. I think what would be of use for a trace > facility is as high-level a view as possible of the message contents. > > Or, in other words: a large part of the problem with the existing PQtrace > facility is that it *was* designed to help debug libpq itself, and that > use-case is no longer very interesting. We should assume that the library > knows how to parse protocol messages. Since I explained the reason in the previous email, I am copy-pasting it again here. I think the purpose of the leveling is to provide an optional information for the user, which is useful for diagnosis during the performance deterioration. When query delay happens, we want to know from which side(server or client) is the cause of it, and then people want to know which process takes time. I think the phase and time information are useful for diagnosis. For example, when command processing function (ex. PQexec()) etc. start/end and when client receive/send protocol messages. So is it alright to add these information to the new/proposed PQtrace() default output? Regards, Aya Iwata
RE: [PATCH] get rid of StdRdOptions, use individual binary reloptions representation for each relation kind instead
Hi Nikolay, This patch does not apply. Please refer to http://commitfest.cputube.org/ and update it. How about separating your patch by feature or units that can be phased commit. For example, adding assert macro at first, refactoring StdRdOptions by the next, etc. So I change status to "Waiting for Author". Regards, Aya Iwata
RE: [PATCH] get rid of StdRdOptions, use individual binary reloptions representation for each relation kind instead
Hi, > hio.c: > > -saveFreeSpace = RelationGetTargetPageFreeSpace(relation, > - > HEAP_DEFAULT_FILLFACTOR); > +if (IsToastRelation(relation)) > +saveFreeSpace = ToastGetTargetPageFreeSpace(); > +else > +saveFreeSpace = HeapGetTargetPageFreeSpace(relation); > > This locution appears four times in the patch and that's the all where the > two macros appear. And it might not be good that RelationGetBufferForTuple > identifies a heap directly since I suppose that currently tost is a part of > heap. Thus it'd be better that HeapGetTargetPageFreeSpace handles the toast > case. > Similary, it doesn't looks good that RelationGetBufferForTuple consults > HeapGetTargretPageFreeSpace() directly. Perhaps it should be called via > TableGetTargetPageFreeSpace(). I'm not sure what is the right shape of the > relationship among a relation and a table and other kinds of relation. > extract_autovac_opts penetrates through the modularity boundary of > toast/heap in a similar way. I think so, too. And In current codes, RelationGetTargetPageFreeSpace users(ex. heap_page_prune_opt) don't have to think whatever target is toast or heap, but in your change, they need to use them properly. You told us "big picture" about opclass around the beginning of this thread. In my understanding, the purpose of this refactoring is to make reloptions more flexible to add opclass. I understand this change may be needed for opclass, however I think that this is not the best way to refactor reloption. How about discussing more about this specification including opclass, and finding the best way to refactor reloption? I have not read the previous thread tightly, so you may have already started preparing. Regards, Aya Iwata
RE: libpq debug log
Hi,
> The basic idea being:
>
> - Each line is a whole message.
> - The line begins with <<< for a message received and >>> for a message sent.
> - Strings in single quotes are those sent/received as a fixed number of bytes.
> - Strings in double quotes are those sent/received as a string.
> - 4-byte integers are printed unadorned.
> - 2-byte integers are prefixed by #.
> - I guess 1-byte integers would need some other prefix, maybe @ or ##.
I created v1 patch to improve PQtrace(); output log message in one line.
Please find my attached patch.
Log output examples;
In current PQtrace log:
To backend> Msg Q
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60
I changed like this:
2019-04-04 02:39:51.488 UTC > Query 59 "SELECT
pg_catalog.set_config('search_path', '', false)"
In current PQtrace log:
>From backend> T
>From backend (#4)> 35
>From backend (#2)> 1
>From backend> "set_config"
>From backend (#4)> 0
>From backend (#2)> 0
>From backend (#4)> 25
>From backend (#2)> 65535
>From backend (#4)> -1
>From backend (#2)> 0
I changed like this:
2019-04-04 02:39:51.489 UTC < RowDescription 35 #1 "set_config" 0 #0 25 #65535
-1 #0
> I would like to add timestamp per line and when command processing function
> start/end.
> I think it is useful to know the application process start/end for diagnosis.
> So I will implement like this;
>
> 2019-03-03 07:24:54.142 UTC PQgetResult start
> 2019-03-03 07:24:54.143 UTC < 'T' 35 1 "set_config" 0 #0 25 #65535 -1 #0
> 2019-03-03 07:24:54.144 UTC PQgetResult end
I would like to add this in next patch if there are not any disagreement.
Regards,
Aya Iwata
v1-0001-libpq-PQtrace-output_one_line.patch
Description: v1-0001-libpq-PQtrace-output_one_line.patch
RE: libpq debug log
Hi,
I update patch to improve PQtrace(); output log message in one line.
Please find my attached patch.
How it changed:
> > The basic idea being:
> >
> > - Each line is a whole message.
> > - The line begins with <<< for a message received and >>> for a message
> sent.
> > - Strings in single quotes are those sent/received as a fixed number of
> bytes.
> > - Strings in double quotes are those sent/received as a string.
> > - 4-byte integers are printed unadorned.
> > - 2-byte integers are prefixed by #.
> > - I guess 1-byte integers would need some other prefix, maybe @ or ##.
New log output examples:
The message sent from frontend is like this;
2019-04-04 02:39:51.488 UTC > Query 59 "SELECT
pg_catalog.set_config('search_path', '', false)"
The message sent from backend is like this;
2019-04-04 02:39:51.489 UTC < RowDescription 35 #1 "set_config" 0 #0 25 #65535
-1 #0
Regards,
Aya Iwata
v2-0001-libpq-PQtrace-output_one_line.patch
Description: v2-0001-libpq-PQtrace-output_one_line.patch
RE: Contribution to Perldoc for TestLib module in Postgres
Hi Ram, I think this documentation helps people who want to understand functions. >Please find the updated patch. Added to the commitfest as well I have some comments. I think some users who would like to know custom function check src/test/perl/README at first. How about add comments to the README file, such as "See Testlib.pm if you want to know more details"? In the above document, why not write a description after the function name? I think it is better to write the function name first and then the description. In your code; #Checks if all the tests passed or not all_tests_passing() In my suggestion; all_tests_passing() Checks if all the tests passed or not And some functions return value. How about adding return information to the above doc? I find ^M character in your new code. Please use LF line ending not CRLF or get rid of it in next patch. Regards, Aya Iwata
RE: libpq debug log
Hi Horiguchi-san,
Thank you for your reviewing.
I updated patch. Please see my attached patch.
> +/* protocol message name */
> +static char *command_text_b[] = {
>
> Couldn't the name be more descriptive? The comment just above doesn't seem
> consistent with the variable. The tables are very sparse. I think the
> definition could be in more compact form.
Thank you. I changed the description more clear.
>
> + /* y */ 0,
> + /* z */ 0
> +};
> +#define COMMAND_BF_MAX (sizeof(command_text_bf) /
> +sizeof(*command_text_bf))
>
> It seems that at least the trailing 0-elements are not required.
Sure. I removed.
> + * message_get_command_text:
> + * Get Protocol message text from byte1 identifier
> + */
> +static char *
> +message_get_command_text(unsigned char c, CommunicationDirection
> +direction)
> ..
> +message_nchar(PGconn *conn, const char *v, int length,
> +CommunicationDirection direction)
>
> Also the function names are not very descriptive.
Thank you. I fixed function names and added descriptions.
>
> +message_Int(PGconn *conn, int v, int length, CommunicationDirection
> +direct)
>
> We are not using names mixing CamelCase and undercored there.
>
>
> + if (c >= 0 && c < COMMAND_BF_MAX)
> + {
> + text = command_text_bf[c];
> + if (text)
> + return text;
> + }
> +
> + if (direction == FROM_BACKEND && c >= 0 && c < COMMAND_B_MAX)
> + {
> + text = command_text_b[c];
> + if (text)
> ..
> + if (direction == FROM_FRONTEND && c >= 0 && c < COMMAND_F_MAX)
>
>
> This code is assuming that elements of command_text_bf is mutually exclusive
> with command_text_b or _bf. That is, the first has an element for 'C', others
> don't have an element in the same position. But _bf[C] = "CommandComplete"
> and _f[C] = "Close". Is it working correctly?
Elements sent from both the backend and the frontend are 'c' and 'd'.
There is no same elements in protocol_message_type_b and _bf.
The same applies to protocol_message_type_f and _bf too. So I think it is
working correctly.
> +typedef enum CommunicationDirection
>
> The type CommunicationDirection is two-member enum which is equivalent to
> just a boolean. Is there a reason you define that?
>
> +typedef enum State
> +typedef enum Type
>
> The name is too generic.
> +typedef struct _LoggingMsg
> ...
> +} LoggingMsg;
>
> Why the tag name is prefixed with an underscore?
>
> +typedef struct _Frontend_Entry
>
> The name doesn't give an idea of its characteristics.
Thank you. I fixed.
Regards,
Aya Iwata
v3-libpq-PQtrace-output-one-line.patch
Description: v3-libpq-PQtrace-output-one-line.patch
RE: psql - add SHOW_ALL_RESULTS option
Hi Fabien, I review your patch. > Add a few tests for the new feature. +++ b/src/test/regress/expected/psql.out @@ -4729,3 +4729,46 @@ drop schema testpart; set search_path to default; set role to default; drop role testrole_partitioning; +-- There is space (+--' '). Please delete it. It is cause of regression test failed. > IMHO this new setting should be on by default: few people know about \; so > it would not change anything for most, and I do not see why those who use > it would not be interested by the results of all the queries they asked for. I agree with your opinion. I test some query combination case. And I found when warning happen, the message is printed in head of results. I think it is not clear in which query the warning occurred. How about print warning message before the query that warning occurred? For example, -- devide by ';' postgres=# BEGIN; BEGIN; SELECT 1 AS one; COMMIT; BEGIN; BEGIN; SELECT 1 AS one; COMMIT; BEGIN psql: WARNING: there is already a transaction in progress BEGIN one - 1 (1 row) COMMIT BEGIN psql: WARNING: there is already a transaction in progress BEGIN one - 1 (1 row) COMMIT -- devide by '\;' and set SHOW_RESULT_ALL on postgres=# \set SHOW_ALL_RESULTS on postgres=# BEGIN\; BEGIN\; SELECT 1 AS one\; COMMIT\; BEGIN\; BEGIN\; SELECT 1 AS one\; COMMIT; psql: WARNING: there is already a transaction in progress BEGIN BEGIN one - 1 (1 row) psql: WARNING: there is already a transaction in progress COMMIT BEGIN BEGIN one - 1 (1 row) COMMIT I will check the code soon. Regards, Aya Iwata
RE: libpq debug log
Hi Kirk, Thank you for your reviewing. > Docs: > It would be better to have reference to the documentations of Frontend/Backend > Protocol's "Message Format". I added a link to "Protocol's Message Formats" and little explanation to PQtrace() documentation. > Code: > There are some protocol message types from frontend that you missed indicating > (non BYTE1 types): > CancelRequest (F), StartupMessage (F), SSLRequest (F). > > Although I haven't tested those actual protocols, I assume it will be printed > as the following since the length and message will still be recognized. > ex. Timestamp 8 80877103 > > So you need to indicate these protocol message types as intended. > ex. Timestamp > SSLRequest 8 80877103 Thank you. I changed code to output these information. For that, I added code to check the int32 content which StartupMessage (F) and SSLRequest (F) have. And CancelRequest is not targeted because it calls send() directly. Regards, Aya Iwata v4-libpq-PQtrace-output-one-line.patch Description: v4-libpq-PQtrace-output-one-line.patch
RE: Function for listing archive_status directory
Hi Christoph, > > All similar function are named pg_ls_***dir. It is clear these > > functions return directory contents information. > > If the new function intends to display the contents of the directory, > > pg_ls_***dir style might be better (e.g. pg_ls_archive_statusdir). > > But everyone know archive_status is a directory... > > If you want to follow the standard naming, then you may add the dir. > > I conciously omitted the "_dir" suffix - I'm not a great fan of long function > names, and we want to inspect the contents of archive_status to find out about > the status of the archiving process. But then, my main concern is the > functionality, not the name, we can easily change the name. Is there any other > opinion pro/contra the name? I understand the reason why you have decided that name. And I agree with your opinion. This function is useful for knowing about the status of archive log. I didn't find any problems with the patch, so I'm marking it as "Ready for Committer". Regards, Aya Iwata
RE: Function for listing archive_status directory
> I didn't find any problems with the patch, so I'm marking it as "Ready for > Committer". Sorry, I made a mistake. You patch currently does not apply. Kindly rebase the patch. I'm marking it as "Waiting on Author". Regards, Aya Iwata
RE: libpq debug log
Hi,
I create a first libpq trace log patch.
In this patch,
- All message that PQtrace() gets are output to the libpq trace log file
(I maybe select more effective message in the future patch)
- Trace log output style is changed slightly from previously proposed
This patch not include documentation,
but you can see parameter detail and how to use it by looking at my previous
e-mail.
If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize.
These parameters are set in the environment variable or the connection service
file.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size(M). When the log file size exceeds to
PGLOGSIZE, the log is output to another file.
The log file name is determined as follow.
libpq-%ProcessID-%Y-%m-%d_%H%M%S.log
Trace log example;
Start : 2018/10/30 08:02:24.433...
time(a)
Query: SELECT pg_catalog.set_config('search_path', '', false)
To backend> Msg Q
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60
Start sending message to backend: 2018/10/30 08:02:24.433 ...
time(b)
End sending message to backend: 2018/10/30 08:02:24.433...
time(c)
Start receiving message from backend: 2018/10/30 08:02:24.434 ... time(d)
End receiving message from backend: 2018/10/30 08:02:24.434... time(e)
>From backend> T
>From backend (#4)> 35
>From backend (#2)> 1
>From backend> "set_config"
>From backend (#4)> 0
>From backend (#2)> 0
>From backend (#4)> 25
>From backend (#2)> 65535
>From backend (#4)> -1
>From backend (#2)> 0
>From backend> D
>From backend (#4)> 10
>From backend (#2)> 1
>From backend (#4)> 0
>From backend> C
>From backend (#4)> 13
>From backend> "SELECT 1"
>From backend> Z
>From backend (#4)> 5
>From backend> Z
>From backend (#4)> 5
>From backend> I
End : 2018/10/30 08:02:24.435 ... time(f)
>From time(a) to time(b): time for libpq processing
>From time(b) to time(c): time for traffic
>From time(c) to time(d): time for backend processing
>From time(d) to time(e): time for traffic
>From time(e) to time(f): time for libpq processing
Regards,
Aya Iwata
v1-0001-libpq-trace-log.patch
Description: v1-0001-libpq-trace-log.patch
RE: libpq debug log
Hi Jim Doty san, Thank you for review! I'm sorry my late reply... > Initial Pass > > > + Patch applies > + Patch builds > + Patch behaves as described in the thread Thank you for your check. > When I set a path for `PGLOGDIR` that didn't exist or was not write-able, > the patch writes no files, and does not alert the user that no files are being > written. I understand. I think it means that it is necessary to confirm how the setting is going well. There is no warning method when connection string or the environment variable is wrong. So I added following document: + If the setting of the file path by the connection string or the environment variable is + incorrect, the log file is not created in the intended location. + The maximum log file size you set is output to the beginning of the file, so you can check it. And I added the process. Please see my v2 patch. > Performance > === > > I ran two permutations of make check, one with the patch applied but not > activated, and the other with with the files being written to disk. Each > permutation was run ten times, and the stats are below (times are in > seconds): > > min max median mean > not logging 50.4 57.653.3 53.4 > logging 58.3 77.765.0 65.8 Thank you for your measurement. I'm thinking about adding a logging level so that only the necessary information can be printed by default. It was pointed out by Haribabu san's e-mail. This minimizes the impact of logging on performance. Regards, Aya Iwata v2-0001-libpq-trace-log.patch Description: v2-0001-libpq-trace-log.patch
RE: libpq debug log
Hi Hari san, Thank you for your comment! And sorry my late reply… >I have some comments related to the trace output that is getting >printed. The amount of log it is generating may not be understood >to many of the application developers. IMO, this should print >only the necessary information that can understood by any one >by default and full log with more configuration? I understand. And I agree your opinion. I will add feature called “log level” that changes the amount of log output information with my future version patch. Regards, Aya Iwata
RE: libpq debug log
Hi Jacob san, Thank you for your comment! And sorry for late reply... > Couple additional thoughts from a read-through of the patch: > > - PQtrace() and the new trace-logging machinery overlap in some places but > not others -- and if both are set, PQtrace() will take precedence. > It seems like the two should not be separate. I understand. This log is acquired for the purpose of investigating the cause part (server side or application side) when performance is bad. So I will search whether getting other place of PQtrace() is necessary or not. And I will reply after the research, please wait for a while a little. > - It isn't immediately clear to me how the new information in the logs is > intended to be used in concert with the old information. Maybe this goes back > to the comments by Tom and Robert higher in the thread -- that an overhaul > of the PQtrace system is due. This patch as presented would make things a > little worse before they got better, I think. > > That said, I think the overall idea -- application performance information > that can be enabled via the environment, without requiring debugging > privileges on a machine or the need to manually correlate traces made by other > applications -- is a good one, and something I would use. Thank you. I think so, too. Some applications cannot be stopped to add the PQtrace() code. Regards, Aya Iwata
RE: libpq debug log
Hi, I created a new version patch. Please find attached my patch. Changes: Since v2 patch I forgot to write the detail of v2 patch changes. So I write these. - Fixed the " Start receiving message from backend:" message location. Because I found that message located at outside of "retry4". - Changed location where output "start :" / "end :" messages and timestamp. The reason of the change is that v1 patch did not correspond to Asynchronous Command Processing. - Added documentation - Added documentation how to check mistake of logdir and/or logsize. (Based on review comment of Jim san's) Since v3 patch - Fixed my mistake on fe-connect.c. Time and message were output at the place where does not output in originally PQtrace(). These messages are needed only new trace log. So I fixed it. - Fixed two points so that new trace log overlaps all places in PQtrace(). (Based on review comment of Jacob san's) TODO: I will add the feature called "logging level" on next version patch. I will attach it as soon as possible. I'm marking it as "Needs review". Regards, Aya Iwata v3-0001-libpq-trace-log.patch Description: v3-0001-libpq-trace-log.patch
RE: libpq debug log
Hi Peter, Thank you for your reply! > On 27/11/2018 08:42, Iwata, Aya wrote: > > I created a new version patch. Please find attached my patch. > > This does not excite me. It seems mostly redundant with using tcpdump. I will develop "log level". I'm planning not to output redundant message at the default level. > If I were to debug networking problems, I wouldn't even trust this very much > because it relies on the willpower of all future PostgreSQL developers to > keep this accurately up to date, whereas tcpdump gives me the truth from the > kernel. I agree your concern about log trusty. It would be a good choice for only skilled users to use tcpdump. I think libpq trace log will be used many users, it includes users who not familiar with PostgreSQL protocols. The log would be easier to use because it shows "start time" and "end time". On tcpdump also shows the starting time and ending time but people need to know PostgreSQL protocol to get them. And this log also is useful for Windows users. Windows does not have originally networking trace tool. If you have any ideas about maintain this feature, I would like to know it. Regards, Aya Iwata
RE: libpq debug log
Hi Nagaura-san, Thank you for your review and advice. > This merit was very helpful for my use, so I want your proposal function in > postgres. Thank you. > 1) > It would be better making the log format the same as the server log format, > I think. > Your log format: > 2019/01/22 04:15:25.496 ... > Server log format: > 2019-01-22 04:15:25.496 UTC ... > There are two differences: > One is separator character of date, "/" and "-". > The another is standard time information. Sure. I will change separator character to "-" and add timezone information. > 2) > It was difficult for me to understand the first line message in the log file. > "Max log size is 10B, log min level is LEVEL1" > Does this mean as follows? > "The maximum size of this file is 10 Bytes, the parameter 'log min level' > is set to LEVEL 1." Yes. The purpose of the line message is to check the value of the set parameter. I will change it to you suggest. > 3) > Under the circumstance that the environment variables "PGLOGDIR" and > "PGLOGSIZE" are set correctly, the log file will also be created when the > user connect the server with "psql". > Does this follow the specification you have thought? > Is there any option to unset only in that session when you want to connect > with "psql"? There are no option to not output log when connected by "psql". It is not good to create lots of empty files. I think that the cause of this issue is that the initialization location of the new trace log is not good. I will fix it so that logs are not output when connected to "psql". > 4) > Your patch affects the behavior of PQtrace(). > The log of the existing PQtrace() is as follows: > From backend> "id" > From backend (#4)> 16387 > From backend (#2)> 1 > From backend (#4)> 23 > ... > Your patch makes PQtrace() including the following log in addition to the > above. > To backend> Msg complete, length 27 > Start sending message to backend:End sending message to backend:PQsendQuery > end :PQgetResult start :Start receiving message from backend:End receiving > message from backend:From backend> T ... Thank you for finding it. I will fix not to affect PQtrace(). Regards, Aya Iwata
RE: libpq compression
Hi,
I am sorry for my late reply.
> I fixed all issues you have reported except using list of supported
> compression
> algorithms.
Sure. I confirmed that.
> It will require extra round of communication between client and server to
> make a decision about used compression algorithm.
In beginning of this thread, Robbie Harwood said that no extra communication
needed.
I think so, too.
> I still not sure whether it is good idea to make it possible to user to
> explicitly specify compression algorithm.
> Right now used streaming compression algorithm is hardcoded and depends on
> --use-zstd ort --use-zlib configuration options.
> If client and server were built with the same options, then they are able
> to use compression.
I understand that compression algorithm is hardcoded in your proposal.
However given the possibility of future implementation, I think
it would be better for it to have a flexibility to choose compression library.
src/backend/libpq/pqcomm.c :
In current Postgres source code, pq_recvbuf() calls secure_read()
and pq_getbyte_if_available() also calls secure_read().
It means these functions are on the same level.
However in your change, pq_getbyte_if_available() calls pq_recvbuf(),
and pq_recvbuf() calls secure_read(). The level of these functions is
different.
I think the purpose of pq_getbyte_if_available() is to get a character if it
exists and
the purpose of pq_recvbuf() is to acquire data up to the expected length.
In your change, pq_getbyte_if_available() may have to do unnecessary process
waiting or something.
So how about changing your code like this?
The part that checks whether it is compressed is implemented as a #define
macro(like fe_misc.c). And pq_recvbuf() and pq_getbyte_if_available() modify
little, like this;
- r = secure_read(MyProcPort, PqRecvBuffer + PqRecvLength,
- PQ_RECV_BUFFER_SIZE -
PqRecvLength);
+r = SOME_DEFINE_NAME_();
configure:
Adding following message to the top of zlib in configure
```
{$as_echo "$as_me:${as_lineno-$LINENO}:checking whethere to build with zstd
support">&5
$as_echo_n "checking whether to build with zstd suppor... ">&6;}
```
Regards,
Aya Iwata
RE: libpq debug log
Hi, Because I mistook something about how to reply to e-mails, my last reply is not reflected in the thread. Response to Nagaura san's review point, I fixed all his review notes, except for pointing out about psql. Please see the attached updated patch. > 1) > It would be better making the log format the same as the server log format, I changed date style and added timezone. > 2) > It was difficult for me to understand the first line message in the log file. I changed the message as "The maximum size of this log is 3 Bytes, the parameter 'logminlevel' is set to level2 ". > 3) > Under the circumstance that the environment variables "PGLOGDIR" and > "PGLOGSIZE" are set correctly, the log file will also be created when the > user connect the server with "psql". > Does this follow the specification you have thought? > Is there any option to unset only in that session when you want to connect > with "psql"? By separating session using Tera Term or screen command, you can do what you want. So I didn't make the code complicated by implementing the option. > 4) > Your patch affects the behavior of PQtrace(). Thank you. I fixed. Regards, Aya Iwata v6-0001-libpq-trace-log.patch Description: v6-0001-libpq-trace-log.patch
RE: libpq debug log
Hi Ramanarayana, Thank you for your review and suggestion. Please see the attached updated patch. > Issues found while testing >1) If invalid value is given to PGLOGMINLEVEL, empty log file is created which >should not happen. Thank you for your test. However in my dev environment, empty log file is not created. Could you explain more detail about 1)? I will check it again. >2) If log file size exceeds the value configured in PGLOGSIZE, new log file is >not getting created. About 2) (and may be 1) ), perhaps is this something like that? There are my mistake about first line information of created log file "The maximum size of this log is %s *Bytes*, the parameter 'logminlevel' is set to %s\n". - Maximum size is not bytes but megabytes. - Display logminlevel which set by user. Internally, an invalid value is not set to logminlevel. So trust the created log file first line info, if you set PGLOGSIZE=1000 as the meaning of "set maximum log size to 1000 Bytes", a new file was not created even if it exceeds 1000 bytes. If it is correct, I fixed the comment to output internal setting log maximum size and user setting value. And if you set PGLOGMINLEVEL to invalid value (ex. "aaa"), it is not set to the parameter; The default value (level1) is set internally. I fixed first line comment to output notification " if invalid value, level1(default) is set". >3) If PGLOGSIZE is greater than 2048 bytes, log file is not created. Is this >expected behavior? Yes. I limit log file size. >4) In the log file, an extra new line is present whenever the query is >printed. Is this intentional? Thank you, I fixed. >5)Documentation for this feature is having grammatical errors and some >spelling errors which can be looked into. Thank you. I am checking my documentation now. I will fix it. > Feedback in the code Thank you. I fixed my code issue. > Suggestions I'll consider that... Could you explain more about the idea? Regards, Aya Iwata v7-0001-libpq-trace-log.patch Description: v7-0001-libpq-trace-log.patch
RE: libpq debug log
Hi Kirk, > Currently, the patch fails to build according to CF app. > As you know, it has something to do with the misspelling of function. > GetTimezoneInformation --> GetTimeZoneInformation Thank you. I fixed it. Please see my v7 patch. Regards, Aya Iwata
RE: libpq debug log
Hi Robert, > I'm not really sure that I like the design of this patch in any way. Aside from problems with my current documentation which I will fix, could you explain more detail about the problem of the design? I would like to improve my current implementation based from feedback. Regards, Aya Iwata
RE: libpq debug log
Hi, > TODO: > I will add the feature called "logging level" on next version patch. I will > attach it as soon as possible. I created v4 patch. Please find attached the patch. This patch developed "logminlevel" parameter. level1 and level2 can be set, level1 is the default. If level1 is set, it outputs the time in the functions. It helps to find out where it takes time. If level2 is set, it outputs information on the protocol being exchanged in addition to level1 information. I would appreciate if you could review my latest patch. Regards, Aya Iwata v4-0001-libpq-trace-log.patch Description: v4-0001-libpq-trace-log.patch
RE: libpq debug log
Hi, I created v5 patch. Please find attached the patch. This patch updated following items; - Changed "else if" to "if" in traceLog_fprintf(). This means that both PQtrace() and new trace log are set, you can get both log result. - Implemented loglevel with enum. This change makes it easier if you want to add new log levels. - Checked http://commitfest.cputube.org/, I modified the code slightly. I would appreciate if you could review my latest patch. Regards, Aya Iwata v5-0001-libpq-trace-log.patch Description: v5-0001-libpq-trace-log.patch
RE: libpq compression
Hi, > > I agree with the critiques from Robbie Harwood and Michael Paquier > > that the way in that compression is being hooked into the existing > > architecture looks like a kludge. I'm not sure I know exactly how it > > should be done, but the current approach doesn't look natural; it > > looks like it was bolted on. > > After some time spend reading this patch and investigating different points, > mentioned in the discussion, I tend to agree with that. As far as I see it's > probably the biggest disagreement here, that keeps things from progressing. > I'm interested in this feature, so if Konstantin doesn't mind, I'll post in > the near future (after I'll wrap up the current CF) an updated patch I'm > working > on right now to propose another way of incorporating compression. For now > I'm moving patch to the next CF. This thread seems to be stopped. In last e-mail, Dmitry suggest to update the patch that implements the function in another way, and as far as I saw, he has not updated patch yet. (It may be because author has not responded.) I understand big disagreement is here, however the status is "Needs review". There is no review after author update the patch to v9. So I will do. About the patch, Please update your patch to attach current master. I could not test. About Documentation, there are typos. Please check it. I am waiting for the reviewer of the sentence because I am not so good at English. When you add new protocol message, it needs the information of "Length of message contents in bytes, including self.". It provides supported compression algorithm as a Byte1. I think it better to provide it as a list like the NegotiateProtocolVersion protocol. I quickly saw code changes. + nread = conn->zstream + ? zpq_read(conn->zstream, conn->inBuffer + conn->inEnd, + conn->inBufSize - conn->inEnd, &processed) + : pqsecure_read(conn, conn->inBuffer + conn->inEnd, + conn->inBufSize - conn->inEnd); How about combine as a #define macro? Because there are same logic in two place. Do you consider anything about memory control? Typically compression algorithm keeps dictionary in memory. I think it needs reset or some method. Regards, Aya Iwata
RE: libpq debug log
Hi, I have developed a new libpq trace logging aimed at checking which side (server or client) is causing the performance issue. The new libpq trace log can do the following things; - Setting whether to get log or not by using connection strings or environment variables. It means that application source code changes is not needed to get the log. - Getting time when receive and send process start/end. Functions too. - Setting log level; When level1(default) is set, it outputs the time in the function and connection time. When level2 is set, it outputs information on the protocol message being exchanged, in addition to level1 information. I updated patch, but I am not sure if these changes and implementation are correct or not. So I need your comment and advice. I would appreciate your advice and develop/fix my patch further. Regards, Aya Iwata
RE: libpq debug log
Hi, I rebased my patch from head. Please find my attached patch. Regard, Aya Iwata v5-libpq-PQtrace-output-one-line.patch Description: v5-libpq-PQtrace-output-one-line.patch
RE: libpq debug log
Hi,
This is a summary of the whole thread.
I am currently improving PQtrace() by adjusting its output to one line per
protocol message as per the advice of reviewers.
Purpose:
If a problem occurs, such as a slow query, you want to know which query takes
time.
In Current libpq, there is PQtrace(FILE *filename) facility to output
exchanging protocol messages to file.
But I think current PQtrace() has following issues:
* The output is confusing. It is difficult to analyze information because it is
printed one by one, and only a character representing a message (ex. printed
'T' means RowDescription).
* Timestamp is not output. So we cannot identify which process took a long
time. That would be possible when we compare timestamps.
* PQtrace() code must be included in libpq application's source code. If you
want to get log, you should change code and re-compile it for logging. Some
application cannot do this.
Compared to tcpdump:
There is tcpdump for similar use, but it has the following problems:
- Windows users cannot use it.
- If the communication is encrypted, it is possible that you may not see the
information you want as explained by Andres.
- Information can only be retrieved by limited users due to OS permissions.
Solution:
Work on following improvements in order:
1. Adjusting it to emit one line per protocol message and output timestamp.
2. Enables logging control without recompiling the application.
I thought it would be better to control it with parameters. However since
this method is controversial (Security implications, etc.), we will consider a
good method after completing 1.
Latest patch just contains 1. Hence, the usage of this feature is the same as
current PQtrace().
Example of log output:
In current PQtrace log:
To backend> Msg Q
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60
I changed like this:
2019-04-04 02:39:51.488 UTC > Query 59 "SELECT
pg_catalog.set_config('search_path', '', false)"
I appreciate your advice regarding the one line protocol message. Thank you in
advance.
Regards,
Aya Iwata
v6-libpq-PQtrace-output-one-line.patch
Description: v6-libpq-PQtrace-output-one-line.patch
RE: hostorder and failover_timeout for libpq
Hello Ildar, I have a question about failover_timeout parameter. Which would be better: implementing the parameter to retry at waiting time or controlling the connection retry on the application side? Also, I have no idea if the amount of random access by hostorder parameter will have a good effect on load balancing. Please let me know if there are examples. I am sorry if these were examined by the previous thread. I haven't read it yet. Regards, Aya Iwata
libpq debug log
Hi, I'm going to propose libpq debug log for analysis of queries on the application side. I think that it is useful to determine whether the cause is on the application side or the server side when a slow query occurs. The provided information is "date and time" at which execution of processing is started, "query", "application side processing", which is picked up information from PQtrace(), and "connection id", which is for uniquely identifying the connection. To collect the log, set the connection string or environment variable. - logdir or PGLOGDIR : directory where log file written - logsize or PGLOGSIZE : maximum log size What do you think about this? Do you think that such feature is necessary? Regards, Aya Iwata
RE: libpq debug log
> "Iwata, Aya" writes: > > I'm going to propose libpq debug log for analysis of queries on the > > application > side. > > I think that it is useful to determine whether the cause is on the > > application > side or the server side when a slow query occurs. > > Hm, how will you tell that really? And what's the advantage over the existing > server-side query logging capability? The log I would like to propose is used when the performance issue happen, system administrator knows the process of application internally and check if there is any problem. "debug" is not the correct description of the feature. The correct one should be "trace". Should I create another thread? > > The provided information is "date and time" at which execution of processing > is started, "query", "application side processing", which is picked up > information from PQtrace(), and "connection id", which is for uniquely > identifying the connection. > > PQtrace() is utterly useless for anything except debugging libpq internals, > and it's not tremendously useful even for that. Don't bother with that part. My initial intention was to get only useful information from PQTrace () since it acquires a lot of information. Is there another way to obtain application side information besides PQTrace() ? > Where will you get a "unique connection id" from? When collecting trace log file in the application side, I think it is necessary to identify different connection. In order to do this, when new empty PQconn structure is created, new connection id is also created. Then we output it in the trace log file for one application. > How will you deal with asynchronously-executed queries --- either the > PQgetResult style, or the single-row-at-a-time style? In my understanding, PQgetResult style outputs logs of multiple result queries at once, While the single-row-at-a-time style outputs log for each query. Is this correct? I think PQgetResult style is better, because this style traces the internal process of the application. Regards, Aya Iwata
RE: libpq debug log
> > I'm going to propose libpq debug log for analysis of queries on the > > application > side. > > I think that it is useful to determine whether the cause is on the > > application > side or the server side when a slow query occurs. > > Do you mean you want to monitor the protocol message exchange at the client > side to analyze performance issues, right? Actually, this might be useful to > determin where is the problem, for example, the client application, the > backend > PostgreSQL, or somewhere in the network. > > Such logging can be implemented in the application, but if libpq provides the > standard way, it would be helpful to resolve a problem without modifying the > application code. Since I'd like to monitor the information the server and the client exchange, I think monitoring protocol messages is good. When a slow query is occurs, we check this client side trace log. The purpose of this log acquisition I thought is to identify where is the problem: server side, application side or traffic. And if the problem is in application side, checking the trace log to identify what is the problem. > > The provided information is "date and time" at which execution of processing > is started, "query", "application side processing", which is picked up > information from PQtrace(), and "connection id", which is for uniquely > identifying the connection. > > I couldn't image how this is like. Could you show us a sample of log lines in > your head? I am roughly thinking as follows; ... START : 2018/09/03 18:16:35.357 CONNECTION(1) STATUS : Connection SEND MESSAGE : 2018/09/03 18:16:35.358 RECEIVE MESSAGE : 2018/09/03 18:16:35.359 END : 2018/09/03 18:16:35.360 ... START : 2018/09/03 18:16:35.357 CONNECTION(1) QUERY : DECLARE myportal CURSOR FOR select * from pg_database SEND MESSAGE : 2018/09/03 18:16:35.358 RECEIVE MESSAGE : 2018/09/03 18:16:35.359 END : 2018/09/03 18:16:35.360 ... > > To collect the log, set the connection string or environment variable. > > - logdir or PGLOGDIR : directory where log file written > > - logsize or PGLOGSIZE : maximum log size > > How we can specify the log file name? What should happen if a file size > exceeds > to PGLOGSIZE? The log file name is determined as follow. libpq-%ApplicationName-%Y-%m-%d_%H%M%S.log When the log file size exceeds to PGLOGSIZE, the log is output to another file. Regards, Aya Iwata
RE: libpq debug log
Let me explain this trace log in a bit more detail. This log is not turned on in the system by default. Turn it on when an issue occurs and you want to check the information in the application in order to clarify the cause. I will present three use cases for this log. 1. Confirmation on cause of out-of-memory We assume that Out-of-memory occurred in the process of storing the data received from the database. However, the contents or length of the data is not known. A trace log is obtained to find these out and what kind of data you have in which part (i.e. query result when receiving from database). 2. Protocol error confirmation When there is an error in the protocol transmitted from the client and an error occurs in the database server, the protocol sent by the client is checked. When the network is unstable, log is checked whether the database server is receiving protocol messages. 3. Processing delay survey If the processing in the application is slow and the processing in the database is fast, investigate the cause of the processing delay. 4 kind of time can be obtained by the log; Timestamp when SQL started Timestamp when information began to be sent to the backend Timestamp when information is successfully received in the application Timestamp when SQL ended Then the difference between the time is checked to find out which part of process takes time. I reconfirm the function I proposed. If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize. These parameters are set in the environment variable or the connection service file. - logdir or PGLOGDIR : directory where log file written - logsize or PGLOGSIZE : maximum log size. When the log file size exceeds to PGLOGSIZE, the log is output to another file. The log file name is determined as follow. libpq-%ConnectionID-%Y-%m-%d_%H%M%S.log This is a trace log example; ... Start: 2018-09-03 18:16:35.357 Connection(1) Status: Connection Send message: 2018-09-03 18:16:35.358 Receive message: 2018-09-03 18:16:35.359 End: 2018-09-03 18:16:35.360 ... Start: 2018-09-03 18:16:35.357 Connection(1)...(1), (2) Query: DECLARE myportal CURSOR FOR select * from pg_database...(3) Send message: 2018-09-03 18:16:35.358 ...(4) ...(5) Receive message: 2018/09/03 18:16:35.359...(6) ...(7) End: 2018-09-03 18:16:35.360...(8) ... (1) Timestamp when SQL started (2) Connection ID (Identify the connection) (3) SQL statement (4) Timestamp when information began to be sent to the backend (5) send message to backend (Result of query, Protocol messages) (6) Timestamp when information is successfully received in the application (7) receive message from backend (Result of query, Protocol messages) (8) Timestamp when SQL ended Regards, Iwata Aya
RE: libpq debug log
Hi, Sorry for my late response. > Between perf/systemtap/dtrace and wireshark, you can already do pretty much > all of that. Have you looked at those and found anything missing? These commands provide detailed information to us. However, I think the trace log is necessary from the following point. 1. ease of use for users It is necessary to take information that is easy to understand for database users. This trace log is retrieved on the application server side. Not only the database developer but also application developer will get and check this log. Also, some of these commands return detailed PostgreSQL function names. The trace log would be useful for users who do not know the inside of PostgreSQL (e.g. application developers) 2. obtain the same information on all OS Some commands depend on the OS. I think that it is important that the trace log information is compatible to each OS. Regards, Aya Iwata
RE: Function for listing archive_status directory
Hi Christoph, I think it is convenient to be able to check the archive_status directory contents information. I reviewed patch. It applies and passes regression test. I checked the code. It refers to the patch which added pg_ls_waldir() and pg_ls_logdir(), so I think it is good. There is one point I care about. All similar function are named pg_ls_***dir. It is clear these functions return directory contents information. If the new function intends to display the contents of the directory, pg_ls_***dir style might be better (e.g. pg_ls_archive_statusdir). But everyone know archive_status is a directory... If you want to follow the standard naming, then you may add the dir. Do you watch this thread? https://www.postgresql.org/message-id/flat/92f458a2-6459-44b8-a7f2-2add32250...@amazon.com They are also discussing about generic pg_ls function. Regards, Aya Iwata
