More efficient logging with log levels

log-bench
Jack Christensen 2015-09-16 08:20:51 -05:00
parent a2e078597b
commit a1aa06c934
4 changed files with 77 additions and 41 deletions

64
conn.go
View File

@ -34,6 +34,7 @@ type ConnConfig struct {
UseFallbackTLS bool // Try FallbackTLSConfig if connecting with TLSConfig fails. Used for preferring TLS, but allowing unencrypted, or vice-versa UseFallbackTLS bool // Try FallbackTLSConfig if connecting with TLSConfig fails. Used for preferring TLS, but allowing unencrypted, or vice-versa
FallbackTLSConfig *tls.Config // config for fallback TLS connection (only used if UseFallBackTLS is true)-- nil disables TLS FallbackTLSConfig *tls.Config // config for fallback TLS connection (only used if UseFallBackTLS is true)-- nil disables TLS
Logger Logger Logger Logger
LogLevel int
Dial DialFunc Dial DialFunc
} }
@ -56,6 +57,7 @@ type Conn struct {
alive bool alive bool
causeOfDeath error causeOfDeath error
logger Logger logger Logger
logLevel int
mr msgReader mr msgReader
fp *fastpath fp *fastpath
pgsql_af_inet byte pgsql_af_inet byte
@ -111,10 +113,16 @@ func Connect(config ConnConfig) (c *Conn, err error) {
c = new(Conn) c = new(Conn)
c.config = config c.config = config
if c.config.Logger != nil {
c.logger = c.config.Logger if c.config.LogLevel != 0 {
c.logLevel = c.config.LogLevel
} else { } else {
c.logger = dlogger // Preserve pre-LogLevel behavior by defaulting to LogLevelDebug
c.logLevel = LogLevelDebug
}
c.logger = c.config.Logger
if c.logger == nil {
c.logLevel = LogLevelNone
} }
if c.config.User == "" { if c.config.User == "" {
@ -123,12 +131,16 @@ func Connect(config ConnConfig) (c *Conn, err error) {
return nil, err return nil, err
} }
c.config.User = user.Username c.config.User = user.Username
c.logger.Debug("Using default connection config", "User", c.config.User) if c.logLevel >= LogLevelDebug {
c.logger.Debug("Using default connection config", "User", c.config.User)
}
} }
if c.config.Port == 0 { if c.config.Port == 0 {
c.config.Port = 5432 c.config.Port = 5432
c.logger.Debug("Using default connection config", "Port", c.config.Port) if c.logLevel >= LogLevelDebug {
c.logger.Debug("Using default connection config", "Port", c.config.Port)
}
} }
network := "tcp" network := "tcp"
@ -159,17 +171,23 @@ func Connect(config ConnConfig) (c *Conn, err error) {
} }
func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tls.Config) (err error) { func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tls.Config) (err error) {
c.logger.Info(fmt.Sprintf("Dialing PostgreSQL server at %s address: %s", network, address)) if c.logLevel >= LogLevelInfo {
c.logger.Info(fmt.Sprintf("Dialing PostgreSQL server at %s address: %s", network, address))
}
c.conn, err = c.config.Dial(network, address) c.conn, err = c.config.Dial(network, address)
if err != nil { if err != nil {
c.logger.Error(fmt.Sprintf("Connection failed: %v", err)) if c.logLevel >= LogLevelError {
c.logger.Error(fmt.Sprintf("Connection failed: %v", err))
}
return err return err
} }
defer func() { defer func() {
if c != nil && err != nil { if c != nil && err != nil {
c.conn.Close() c.conn.Close()
c.alive = false c.alive = false
c.logger.Error(err.Error()) if c.logLevel >= LogLevelError {
c.logger.Error(err.Error())
}
} }
}() }()
@ -179,9 +197,13 @@ func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tl
c.lastActivityTime = time.Now() c.lastActivityTime = time.Now()
if tlsConfig != nil { if tlsConfig != nil {
c.logger.Debug("Starting TLS handshake") if c.logLevel >= LogLevelDebug {
c.logger.Debug("Starting TLS handshake")
}
if err := c.startTLS(tlsConfig); err != nil { if err := c.startTLS(tlsConfig); err != nil {
c.logger.Error(fmt.Sprintf("TLS failed: %v", err)) if c.logLevel >= LogLevelError {
c.logger.Error(fmt.Sprintf("TLS failed: %v", err))
}
return err return err
} }
} }
@ -215,7 +237,7 @@ func (c *Conn) connect(config ConnConfig, network, address string, tlsConfig *tl
} }
case readyForQuery: case readyForQuery:
c.rxReadyForQuery(r) c.rxReadyForQuery(r)
if c.logger != dlogger { if c.logLevel >= LogLevelInfo {
c.logger = &connLogger{logger: c.logger, pid: c.Pid} c.logger = &connLogger{logger: c.logger, pid: c.Pid}
c.logger.Info("Connection established") c.logger.Info("Connection established")
} }
@ -292,7 +314,9 @@ func (c *Conn) Close() (err error) {
_, err = c.conn.Write(wbuf.buf) _, err = c.conn.Write(wbuf.buf)
c.die(errors.New("Closed")) c.die(errors.New("Closed"))
c.logger.Info("Closed connection") if c.logLevel >= LogLevelInfo {
c.logger.Info("Closed connection")
}
return err return err
} }
@ -460,11 +484,13 @@ func configSSL(sslmode string, cc *ConnConfig) error {
// Prepare creates a prepared statement with name and sql. sql can contain placeholders // Prepare creates a prepared statement with name and sql. sql can contain placeholders
// for bound parameters. These placeholders are referenced positional as $1, $2, etc. // for bound parameters. These placeholders are referenced positional as $1, $2, etc.
func (c *Conn) Prepare(name, sql string) (ps *PreparedStatement, err error) { func (c *Conn) Prepare(name, sql string) (ps *PreparedStatement, err error) {
defer func() { if c.logLevel >= LogLevelError {
if err != nil { defer func() {
c.logger.Error(fmt.Sprintf("Prepare `%s` as `%s` failed: %v", name, sql, err)) if err != nil {
} c.logger.Error(fmt.Sprintf("Prepare `%s` as `%s` failed: %v", name, sql, err))
}() }
}()
}
// parse // parse
wbuf := newWriteBuf(c, 'P') wbuf := newWriteBuf(c, 'P')
@ -853,7 +879,7 @@ func (c *Conn) Exec(sql string, arguments ...interface{}) (commandTag CommandTag
startTime := time.Now() startTime := time.Now()
c.lastActivityTime = startTime c.lastActivityTime = startTime
if c.logger != dlogger { if c.logLevel >= LogLevelError {
defer func() { defer func() {
if err == nil { if err == nil {
endTime := time.Now() endTime := time.Now()
@ -929,7 +955,7 @@ func (c *Conn) rxMsg() (t byte, r *msgReader, err error) {
c.lastActivityTime = time.Now() c.lastActivityTime = time.Now()
if c.logger != dlogger { if c.logLevel >= LogLevelTrace {
c.logger.Debug("rxMsg", "Type", string(t), "Size", c.mr.msgBytesRemaining) c.logger.Debug("rxMsg", "Type", string(t), "Size", c.mr.msgBytesRemaining)
} }

View File

@ -19,6 +19,7 @@ type ConnPool struct {
maxConnections int maxConnections int
afterConnect func(*Conn) error afterConnect func(*Conn) error
logger Logger logger Logger
logLevel int
closed bool closed bool
} }
@ -42,10 +43,16 @@ func NewConnPool(config ConnPoolConfig) (p *ConnPool, err error) {
} }
p.afterConnect = config.AfterConnect p.afterConnect = config.AfterConnect
if config.Logger != nil {
p.logger = config.Logger if config.LogLevel != 0 {
p.logLevel = config.LogLevel
} else { } else {
p.logger = &discardLogger{} // Preserve pre-LogLevel behavior by defaulting to LogLevelDebug
p.logLevel = LogLevelDebug
}
p.logger = config.Logger
if p.logger == nil {
p.logLevel = LogLevelNone
} }
p.allConnections = make([]*Conn, 0, p.maxConnections) p.allConnections = make([]*Conn, 0, p.maxConnections)
@ -92,7 +99,9 @@ func (p *ConnPool) Acquire() (c *Conn, err error) {
// All connections are in use and we cannot create more // All connections are in use and we cannot create more
if len(p.availableConnections) == 0 { if len(p.availableConnections) == 0 {
p.logger.Warn("All connections in pool are busy - waiting...") if p.logLevel >= LogLevelWarn {
p.logger.Warn("All connections in pool are busy - waiting...")
}
for len(p.availableConnections) == 0 { for len(p.availableConnections) == 0 {
p.cond.Wait() p.cond.Wait()
} }

View File

@ -5,6 +5,18 @@ import (
"fmt" "fmt"
) )
// The values for log levels are chosen such that the zero value means that no
// log level was specified and we can default to LogLevelDebug to preserve
// the behavior that existed prior to log level introduction.
const (
LogLevelTrace = 6
LogLevelDebug = 5
LogLevelInfo = 4
LogLevelWarn = 3
LogLevelError = 2
LogLevelNone = 1
)
// Logger is the interface used to get logging from pgx internals. // Logger is the interface used to get logging from pgx internals.
// https://github.com/inconshreveable/log15 is the recommended logging package. // https://github.com/inconshreveable/log15 is the recommended logging package.
// This logging interface was extracted from there. However, it should be simple // This logging interface was extracted from there. However, it should be simple
@ -17,16 +29,6 @@ type Logger interface {
Error(msg string, ctx ...interface{}) Error(msg string, ctx ...interface{})
} }
type discardLogger struct{}
// default discardLogger instance
var dlogger = &discardLogger{}
func (l *discardLogger) Debug(msg string, ctx ...interface{}) {}
func (l *discardLogger) Info(msg string, ctx ...interface{}) {}
func (l *discardLogger) Warn(msg string, ctx ...interface{}) {}
func (l *discardLogger) Error(msg string, ctx ...interface{}) {}
type connLogger struct { type connLogger struct {
logger Logger logger Logger
pid int32 pid int32

View File

@ -52,6 +52,7 @@ type Rows struct {
sql string sql string
args []interface{} args []interface{}
logger Logger logger Logger
logLevel int
} }
func (rows *Rows) FieldDescriptions() []FieldDescription { func (rows *Rows) FieldDescriptions() []FieldDescription {
@ -70,14 +71,12 @@ func (rows *Rows) close() {
rows.closed = true rows.closed = true
if rows.logger == dlogger {
return
}
if rows.err == nil { if rows.err == nil {
endTime := time.Now() if rows.logLevel >= LogLevelInfo {
rows.logger.Info("Query", "sql", rows.sql, "args", logQueryArgs(rows.args), "time", endTime.Sub(rows.startTime), "rowCount", rows.rowCount) endTime := time.Now()
} else { rows.logger.Info("Query", "sql", rows.sql, "args", logQueryArgs(rows.args), "time", endTime.Sub(rows.startTime), "rowCount", rows.rowCount)
}
} else if rows.logLevel >= LogLevelError {
rows.logger.Error("Query", "sql", rows.sql, "args", logQueryArgs(rows.args)) rows.logger.Error("Query", "sql", rows.sql, "args", logQueryArgs(rows.args))
} }
} }
@ -420,7 +419,7 @@ func (rows *Rows) Values() ([]interface{}, error) {
// from Query and handle it in *Rows. // from Query and handle it in *Rows.
func (c *Conn) Query(sql string, args ...interface{}) (*Rows, error) { func (c *Conn) Query(sql string, args ...interface{}) (*Rows, error) {
c.lastActivityTime = time.Now() c.lastActivityTime = time.Now()
rows := &Rows{conn: c, startTime: c.lastActivityTime, sql: sql, args: args, logger: c.logger} rows := &Rows{conn: c, startTime: c.lastActivityTime, sql: sql, args: args, logger: c.logger, logLevel: c.logLevel}
ps, ok := c.preparedStatements[sql] ps, ok := c.preparedStatements[sql]
if !ok { if !ok {