PostgreSQL csvlog 源码字段分析记录

0.前言

PostgreSQL我们配置好相应的配置文件后，就可以在对应目录下生成csv格式的日志文件，打开后发现csv字段还是挺多的，故自己找源码分析并记录。
PostgreSQL因为公司原因才学几天，肯定有错误见谅

1.各字段分析和实例解析

PostgreSQL csvlog日志格式记录了非常多的信息，足有二十多列，在PostgreSQL文档 中例子具体列如下，各字段翻译参考PostgreSQL中文文档

CREATE TABLE postgres_log
(
  log_time timestamp(3) with time zone,#日志时间，带毫秒的时间戳
  user_name text,# 当前登录数据库的用户名
  database_name text,# 数据库名
  process_id integer,# 进程ID
  connection_from text,# 客户端主机:端口号
  session_id text,# 会话ID 由后台进程启动时间和PID组成
  session_line_num bigint,#每个会话的行号，类似history命令
  command_tag text,# 命令标签
  session_start_time timestamp with time zone,# 会话开始时间
  virtual_transaction_id text,# 虚拟事务ID
  transaction_id bigint,# 事务ID
  error_severity text,# 错误等级
  sql_state_code text,# SQLSTATE 代码
  message text,# 消息
  detail text,# 错误消息详情
  hint text,# 提示
  internal_query text,# 导致错误的内部查询（如果有）
  internal_query_pos integer,# 错误位置所在的字符计数
  context text,#  错误上下文
  query text,# 导致错误的用户查询（如果有且被log_min_error_statement启用）
  query_pos integer,# 错误位置所在的字符计数
  location text,# 在 PostgreSQL 源代码中错误的位置（如果log_error_verbosity被设置为verbose）
  application_name text,# 应用名
  PRIMARY KEY (session_id, session_line_num)
);

• message这个字段有点意思：在error_severity 为ERROR时里面是错误原因（表XXX已存在了啥的）；在error_severity 为LOG时，这里会放查询语句和查询时间啥的
• 其中sql_state_code（SQL状态码）可以在官方文档附录中搜索到具体的错误情况。

---

以csv中一条记录为例,当时执行的SQL如下

2021-09-14 23:51:05.272 CST,“postgres”,“postgres”,1169,“[local]”,6140c438.491,5,“idle”,2021-09-14 23:48:08 CST,3/10,0,ERROR,42601,“subquery in FROM must have an alias”,“For example, FROM (SELECT …) [AS] foo.”,“select * from (select id from company where salary>10000 );”,15,"psql

方便观看我把二十多个字段分了组。

1. 第一组连接信息：

字段	值	备注
log_time timestamp	2021-09-14 23:51:05.272 CST	日志记录时间
user_name	postgres	我直接 su - postgres登录的
database_name	postgres	默认数据库
process_id	1169	进程id
connection_from	[local ]	本机
第一组比较简单没啥好说，需要注意的是connection_from 字段是由客户端主机:端口号组成，我这里因为是本机所以没展现效果

2. 第二组session和事务：

字段	值	备注
session_id	6140c438.491	后台进程的启动时间+PID
session_line_num	5	第5条命令
command_tag	idle	idle表示空闲，具体参考下文
session_start_time	2021-09-14 23:48:08 CST	会话开启时间
virtual_transaction_id	3/10	虚拟事务id
transaction_id	0	事务id

• command_tag的idle解释查询自StackOverflow，在官方文档也有相应解释，command_tag其他类型就比较容易看懂了如：SELECT、SHOW、authentication等。
• virtual_transaction_id由两个部分组成，分别是backendid和local transaction id，定义于源码的lock.h文件。虚拟事务ID简单说用来标示锁冲突的对象的，具体用途请参考这篇博客，本文略。

3. 第三组查询详情：

字段	值	备注
error_severity	ERROR	错误等级，这里是ERROR
sql_state_code	42601	sql状态码，42601表示语法错误
message	subquery in FROM must have an alias	错误信息，子查询必须取别名
detail		细节
hint	For example, FROM (SELECT …) [AS] foo.	备注：举例……
internal_query		导致错误的内部查询（如果有）
internal_query_pos		内部错误位置所在的字符计数
context		错误上下文
query	select * from(select id from company where salary>10000 );	完整的查询语句
query_pos	15	错误位置所在的字符计数
location		PostgreSQL 源代码中错误的位置（如果有）
application_name	psql	客户端名称

第三组是最多的，但也比较好懂。

经过上面解释后，可以发现我们最关心的时间、user、connection、SQL语句和错误信息等都可以从csvlog中找到~

2.源码溯源

上一节分析了各字段，现在我们看看这些字段在源码里究竟是怎么赋值的~

PostgreSQL 源码的src/include/utils/elog.h的2762行的write_csvlog方法就是进行csvlog各字段的赋值操作。

/*
  * Constructs the error message, depending on the Errordata it gets, in a CSV
  * format which is described in doc/src/sgml/config.sgml.
  */
 static void
 write_csvlog(ErrorData *edata)
 {
     StringInfoData buf;
     bool        print_stmt = false;
 
     /* static counter for line numbers */
     static long log_line_number = 0;
 
     /* has counter been reset in current process? */
     static int  log_my_pid = 0;
 
     /*
      * This is one of the few places where we'd rather not inherit a static
      * variable's value from the postmaster.  But since we will, reset it when
      * MyProcPid changes.
      */
     if (log_my_pid != MyProcPid)
     {
         log_line_number = 0;
         log_my_pid = MyProcPid;
         formatted_start_time[0] = '\0';
     }
     log_line_number++;
 
     initStringInfo(&buf);
   // 从这里开始，每个字段什么意思都可以看到，每个字段都用appendStringInfoChar(&buf, ',');隔开来了。  
     /*
      * timestamp with milliseconds
      *
      * Check if the timestamp is already calculated for the syslog message,
      * and use it if so.  Otherwise, get the current timestamp.  This is done
      * to put same timestamp in both syslog and csvlog messages.
      */
     if (formatted_log_time[0] == '\0')
         setup_formatted_log_time();
 
     appendStringInfoString(&buf, formatted_log_time);
     appendStringInfoChar(&buf, ',');
 
     /* username */
     if (MyProcPort)
         appendCSVLiteral(&buf, MyProcPort->user_name);
     appendStringInfoChar(&buf, ',');
 
     /* database name */
     if (MyProcPort)
         appendCSVLiteral(&buf, MyProcPort->database_name);
     appendStringInfoChar(&buf, ',');
 
     /* Process id  */
     if (MyProcPid != 0)
         appendStringInfo(&buf, "%d", MyProcPid);
     appendStringInfoChar(&buf, ',');
 
     /* Remote host and port */
     if (MyProcPort && MyProcPort->remote_host)
     {
         appendStringInfoChar(&buf, '"');
         appendStringInfoString(&buf, MyProcPort->remote_host);
         if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
         {
             appendStringInfoChar(&buf, ':');
             appendStringInfoString(&buf, MyProcPort->remote_port);
         }
         appendStringInfoChar(&buf, '"');
     }
     appendStringInfoChar(&buf, ',');
 
     /* session id */
     // session id 是两个字段组成的分别是后台进程的启动时间和PID，所以是唯一的
     appendStringInfo(&buf, "%lx.%x", (long) MyStartTime, MyProcPid);
     appendStringInfoChar(&buf, ',');
 
     /* Line number */
     appendStringInfo(&buf, "%ld", log_line_number);
     appendStringInfoChar(&buf, ',');
 
     /* PS display */
     if (MyProcPort)
     {
         StringInfoData msgbuf;
         const char *psdisp;
         int         displen;
 
         initStringInfo(&msgbuf);
 
         psdisp = get_ps_display(&displen);
         appendBinaryStringInfo(&msgbuf, psdisp, displen);
         appendCSVLiteral(&buf, msgbuf.data);
 
         pfree(msgbuf.data);
     }
     appendStringInfoChar(&buf, ',');
 
     /* session start timestamp */
     if (formatted_start_time[0] == '\0')
         setup_formatted_start_time();
     appendStringInfoString(&buf, formatted_start_time);
     appendStringInfoChar(&buf, ',');
 
     /* Virtual transaction id */
     /* keep VXID format in sync with lockfuncs.c */
     //虚拟事务号由backendid和local transaction id组成
     if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
         appendStringInfo(&buf, "%d/%u", MyProc->backendId, MyProc->lxid);
     appendStringInfoChar(&buf, ',');
 
     /* Transaction id */
     appendStringInfo(&buf, "%u", GetTopTransactionIdIfAny());
     appendStringInfoChar(&buf, ',');
 
     /* Error severity */
     appendStringInfoString(&buf, _(error_severity(edata->elevel)));
     appendStringInfoChar(&buf, ',');
 
     /* SQL state code */
     appendStringInfoString(&buf, unpack_sql_state(edata->sqlerrcode));
     appendStringInfoChar(&buf, ',');
 
     /* errmessage */
     appendCSVLiteral(&buf, edata->message);
     appendStringInfoChar(&buf, ',');
 
     /* errdetail or errdetail_log */
      是否输出代码位置
     if (edata->detail_log)
         appendCSVLiteral(&buf, edata->detail_log);
     else
         appendCSVLiteral(&buf, edata->detail);
     appendStringInfoChar(&buf, ',');
 
     /* errhint */
     appendCSVLiteral(&buf, edata->hint);
     appendStringInfoChar(&buf, ',');
 
     /* internal query */
     appendCSVLiteral(&buf, edata->internalquery);
     appendStringInfoChar(&buf, ',');
 
     /* if printed internal query, print internal pos too */
     if (edata->internalpos > 0 && edata->internalquery != NULL)
         appendStringInfo(&buf, "%d", edata->internalpos);
     appendStringInfoChar(&buf, ',');
 
     /* errcontext */
     if (!edata->hide_ctx)
         appendCSVLiteral(&buf, edata->context);
     appendStringInfoChar(&buf, ',');
 
     /* user query --- only reported if not disabled by the caller */
     if (is_log_level_output(edata->elevel, log_min_error_statement) &&
         debug_query_string != NULL &&
         !edata->hide_stmt)
         print_stmt = true;
     if (print_stmt)
         appendCSVLiteral(&buf, debug_query_string);
     appendStringInfoChar(&buf, ',');
     if (print_stmt && edata->cursorpos > 0)
         appendStringInfo(&buf, "%d", edata->cursorpos);
     appendStringInfoChar(&buf, ',');
 
     /* file error location */
     if (Log_error_verbosity >= PGERROR_VERBOSE)
     {
         StringInfoData msgbuf;
 
         initStringInfo(&msgbuf);
 
         if (edata->funcname && edata->filename)
             appendStringInfo(&msgbuf, "%s, %s:%d",
                              edata->funcname, edata->filename,
                              edata->lineno);
         else if (edata->filename)
             appendStringInfo(&msgbuf, "%s:%d",
                              edata->filename, edata->lineno);
         appendCSVLiteral(&buf, msgbuf.data);
         pfree(msgbuf.data);
     }
     appendStringInfoChar(&buf, ',');
 
     /* application name */
     if (application_name)
         appendCSVLiteral(&buf, application_name);
 
     appendStringInfoChar(&buf, ',');
 
     /* backend type */
     if (MyProcPid == PostmasterPid)
         appendCSVLiteral(&buf, "postmaster");
     else if (MyBackendType == B_BG_WORKER)
         appendCSVLiteral(&buf, MyBgworkerEntry->bgw_type);
     else
         appendCSVLiteral(&buf, GetBackendTypeDesc(MyBackendType));
 
     appendStringInfoChar(&buf, ',');
 
     /* leader PID */
     if (MyProc)
     {
         PGPROC     *leader = MyProc->lockGroupLeader;
 
         /*
          * Show the leader only for active parallel workers.  This leaves out
          * the leader of a parallel group.
          */
         if (leader && leader->pid != MyProcPid)
             appendStringInfo(&buf, "%d", leader->pid);
     }
     appendStringInfoChar(&buf, ',');
 
     /* query id */
     appendStringInfo(&buf, "%lld", (long long) pgstat_get_my_query_id());
 
     appendStringInfoChar(&buf, '\n');
 
     /* If in the syslogger process, try to write messages direct to file */
     if (MyBackendType == B_LOGGER)
         write_syslogger_file(buf.data, buf.len, LOG_DESTINATION_CSVLOG);
     else
         write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_CSVLOG);
 
     pfree(buf.data);
 }

• 源码比较简单，基本上根据原始的注释就能想到具体操作，后面的详细解释，后面来填坑
• write_log(ErrorData *edata)方法传入ErrorData 这样的结构体定义了elog.h头文件中369行，具体定义如下，根据自带的注释也能理解意思

src/include/utils/elog.h
/*
 * ErrorData holds the data accumulated during any one ereport() cycle.
 * Any non-NULL pointers must point to palloc'd data.
 * (The const pointers are an exception; we assume they point at non-freeable
 * constant strings.)
 */
typedef struct ErrorData
{
    int            elevel;            /* error level */
    bool        output_to_server;        /* will report to server log? */
    bool        output_to_client;        /* will report to client? */
    bool        show_funcname;    /* true to force funcname inclusion */
    bool        hide_stmt;        /* true to prevent STATEMENT: inclusion */
    const char *filename;        /* __FILE__ of ereport() call */
    int            lineno;            /* __LINE__ of ereport() call */
    const char *funcname;        /* __func__ of ereport() call */
    const char *domain;            /* message domain */
    const char *context_domain; /* message domain for context message */
    int            sqlerrcode;        /* encoded ERRSTATE */
    char       *message;        /* primary error message */
    char       *detail;            /* detail error message */
    char       *detail_log;        /* detail error message for server log only */
    char       *hint;            /* hint message */
    char       *context;        /* context message */
    char       *schema_name;    /* name of schema */
    char       *table_name;        /* name of table */
    char       *column_name;    /* name of column */
    char       *datatype_name;    /* name of datatype */
    char       *constraint_name;    /* name of constraint */
    int            cursorpos;        /* cursor index into query string */
    int            internalpos;    /* cursor index into internalquery */
    char       *internalquery;    /* text of internally-generated query */
    int            saved_errno;    /* errno at entry */

    /* context containing associated non-constant strings */
    struct MemoryContextData *assoc_context;
} ErrorData;

源码比较简洁
后面再填坑吧我好累/(ㄒoㄒ)/~~

3. 参考

• PostgreSQL-12官方中文文档
• PostgreSQL源码 git master
• PostgreSQL csvlog 源码分析