internal/debug: APIs for profiling and tracing

The debug package provides an RPC wrapper for glog settings and the
debugging facilities of the Go runtime. They can be triggered through
both command line flags and the IPC listener.
This commit is contained in:
Felix Lange 2016-01-26 14:39:21 +01:00
parent e287b56b69
commit 3750d835a1
10 changed files with 502 additions and 107 deletions

@ -20,7 +20,6 @@ package main
import (
"fmt"
"io/ioutil"
_ "net/http/pprof"
"os"
"path/filepath"
"runtime"
@ -34,6 +33,7 @@ import (
"github.com/ethereum/go-ethereum/cmd/utils"
"github.com/ethereum/go-ethereum/common"
"github.com/ethereum/go-ethereum/eth"
"github.com/ethereum/go-ethereum/internal/debug"
"github.com/ethereum/go-ethereum/logger"
"github.com/ethereum/go-ethereum/logger/glog"
"github.com/ethereum/go-ethereum/metrics"
@ -326,12 +326,6 @@ JavaScript API. See https://github.com/ethereum/go-ethereum/wiki/Javascipt-Conso
utils.VMEnableJitFlag,
utils.NetworkIdFlag,
utils.RPCCORSDomainFlag,
utils.VerbosityFlag,
utils.BacktraceAtFlag,
utils.LogVModuleFlag,
utils.LogFileFlag,
utils.PProfEanbledFlag,
utils.PProfPortFlag,
utils.MetricsEnabledFlag,
utils.SolcPathFlag,
utils.GpoMinGasPriceFlag,
@ -342,23 +336,29 @@ JavaScript API. See https://github.com/ethereum/go-ethereum/wiki/Javascipt-Conso
utils.GpobaseCorrectionFactorFlag,
utils.ExtraDataFlag,
}
app.Flags = append(app.Flags, debug.Flags...)
app.Before = func(ctx *cli.Context) error {
runtime.GOMAXPROCS(runtime.NumCPU())
if err := debug.Setup(ctx); err != nil {
return err
}
// Start system runtime metrics collection
go metrics.CollectProcessMetrics(3 * time.Second)
utils.SetupLogger(ctx)
utils.SetupNetwork(ctx)
utils.SetupVM(ctx)
if ctx.GlobalBool(utils.PProfEanbledFlag.Name) {
utils.StartPProf(ctx)
}
return nil
}
// Start system runtime metrics collection
go metrics.CollectProcessMetrics(3 * time.Second)
app.After = func(ctx *cli.Context) error {
logger.Flush()
debug.Exit()
return nil
}
}
func main() {
defer logger.Flush()
if err := app.Run(os.Args); err != nil {
fmt.Fprintln(os.Stderr, err)
os.Exit(1)

@ -23,6 +23,7 @@ import (
"github.com/codegangsta/cli"
"github.com/ethereum/go-ethereum/cmd/utils"
"github.com/ethereum/go-ethereum/internal/debug"
)
// AppHelpTemplate is the test template for the default, global app help topic.
@ -147,16 +148,8 @@ var AppHelpFlagGroups = []flagGroup{
},
},
{
Name: "LOGGING AND DEBUGGING",
Flags: []cli.Flag{
utils.VerbosityFlag,
utils.LogVModuleFlag,
utils.BacktraceAtFlag,
utils.LogFileFlag,
utils.PProfEanbledFlag,
utils.PProfPortFlag,
utils.MetricsEnabledFlag,
},
Name: "LOGGING AND DEBUGGING",
Flags: append([]cli.Flag{utils.MetricsEnabledFlag}, debug.Flags...),
},
{
Name: "EXPERIMENTAL",

@ -18,20 +18,17 @@ package utils
import (
"crypto/ecdsa"
"errors"
"fmt"
"io/ioutil"
"log"
"math"
"math/big"
"net/http"
"os"
"path/filepath"
"runtime"
"strconv"
"strings"
"errors"
"github.com/codegangsta/cli"
"github.com/ethereum/ethash"
"github.com/ethereum/go-ethereum/accounts"
@ -223,35 +220,6 @@ var (
}
// logging and debug settings
VerbosityFlag = cli.IntFlag{
Name: "verbosity",
Usage: "Logging verbosity: 0-6 (0=silent, 1=error, 2=warn, 3=info, 4=core, 5=debug, 6=debug detail)",
Value: int(logger.InfoLevel),
}
LogFileFlag = cli.StringFlag{
Name: "logfile",
Usage: "Log output file within the data dir (default = no log file generated)",
Value: "",
}
LogVModuleFlag = cli.GenericFlag{
Name: "vmodule",
Usage: "Per-module verbosity: comma-separated list of <module>=<level>, where <module> is file literal or a glog pattern",
Value: glog.GetVModule(),
}
BacktraceAtFlag = cli.GenericFlag{
Name: "backtrace",
Usage: "Request a stack trace at a specific logging statement (e.g. \"block.go:271\")",
Value: glog.GetTraceLocation(),
}
PProfEanbledFlag = cli.BoolFlag{
Name: "pprof",
Usage: "Enable the profiling server on localhost",
}
PProfPortFlag = cli.IntFlag{
Name: "pprofport",
Usage: "Profile server listening port",
Value: 6060,
}
MetricsEnabledFlag = cli.BoolFlag{
Name: metrics.MetricsEnabledFlag,
Usage: "Enable metrics collection and reporting",
@ -297,7 +265,7 @@ var (
Value: DirectoryString{common.DefaultIpcPath()},
}
WSEnabledFlag = cli.BoolFlag{
Name: "ws",
Name: "ws",
Usage: "Enable the WS-RPC server",
}
WSListenAddrFlag = cli.StringFlag{
@ -324,6 +292,7 @@ var (
Name: "exec",
Usage: "Execute JavaScript statement (only in combination with console/attach)",
}
// Network Settings
MaxPeersFlag = cli.IntFlag{
Name: "maxpeers",
@ -714,19 +683,6 @@ func MakeSystemNode(name, version string, extra []byte, ctx *cli.Context) *node.
return stack
}
// SetupLogger configures glog from the logging-related command line flags.
func SetupLogger(ctx *cli.Context) {
glog.SetV(ctx.GlobalInt(VerbosityFlag.Name))
glog.CopyStandardLogTo("INFO")
glog.SetToStderr(true)
if ctx.GlobalIsSet(LogFileFlag.Name) {
logger.New("", ctx.GlobalString(LogFileFlag.Name), ctx.GlobalInt(VerbosityFlag.Name))
}
if ctx.GlobalIsSet(VMDebugFlag.Name) {
vm.Debug = ctx.GlobalBool(VMDebugFlag.Name)
}
}
// SetupNetwork configures the system for either the main net or some test network.
func SetupNetwork(ctx *cli.Context) {
switch {
@ -746,6 +702,9 @@ func SetupVM(ctx *cli.Context) {
vm.EnableJit = ctx.GlobalBool(VMEnableJitFlag.Name)
vm.ForceJit = ctx.GlobalBool(VMForceJitFlag.Name)
vm.SetJITCacheSize(ctx.GlobalInt(VMJitCacheFlag.Name))
if ctx.GlobalIsSet(VMDebugFlag.Name) {
vm.Debug = ctx.GlobalBool(VMDebugFlag.Name)
}
}
// MakeChain creates a chain manager from set command line flags.
@ -873,10 +832,3 @@ func StartWS(stack *node.Node, ctx *cli.Context) error {
glog.V(logger.Error).Infof("Unable to start RPC-WS interface, could not find admin API")
return errors.New("Unable to start RPC-WS interface")
}
func StartPProf(ctx *cli.Context) {
address := fmt.Sprintf("localhost:%d", ctx.GlobalInt(PProfPortFlag.Name))
go func() {
log.Println(http.ListenAndServe(address, nil))
}()
}

192
internal/debug/api.go Normal file

@ -0,0 +1,192 @@
// Copyright 2016 The go-ethereum Authors
// This file is part of the go-ethereum library.
//
// The go-ethereum library is free software: you can redistribute it and/or modify
// it under the terms of the GNU Lesser General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// The go-ethereum library is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU Lesser General Public License for more details.
//
// You should have received a copy of the GNU Lesser General Public License
// along with the go-ethereum library. If not, see <http://www.gnu.org/licenses/>.
// Package debug interfaces Go runtime debugging facilities.
// This package is mostly glue code making these facilities available
// through the CLI and RPC subsystem. If you want to use them from Go code,
// use package runtime instead.
package debug
import (
"errors"
"io"
"os"
"os/user"
"path/filepath"
"runtime"
"runtime/pprof"
"strings"
"sync"
"time"
"github.com/ethereum/go-ethereum/logger"
"github.com/ethereum/go-ethereum/logger/glog"
)
// Handler is the global debugging handler.
var Handler = new(HandlerT)
// HandlerT implements the debugging API.
// Do not create values of this type, use the one
// in the Handler variable instead.
type HandlerT struct {
mu sync.Mutex
cpuW io.WriteCloser
cpuFile string
traceW io.WriteCloser
traceFile string
}
// Verbosity sets the glog verbosity floor.
// The verbosity of individual packages and source files
// can be raised using Vmodule.
func (*HandlerT) Verbosity(level int) {
glog.SetV(level)
}
// Vmodule sets the glog verbosity pattern. See package
// glog for details on pattern syntax.
func (*HandlerT) Vmodule(pattern string) error {
return glog.GetVModule().Set(pattern)
}
// BacktraceAt sets the glog backtrace location.
// See package glog for details on pattern syntax.
func (*HandlerT) BacktraceAt(location string) error {
return glog.GetTraceLocation().Set(location)
}
// CpuProfile turns on CPU profiling for nsec seconds and writes
// profile data to file.
func (h *HandlerT) CpuProfile(file string, nsec uint) error {
if err := h.StartCPUProfile(file); err != nil {
return err
}
time.Sleep(time.Duration(nsec) * time.Second)
h.StopCPUProfile()
return nil
}
// StartCPUProfile turns on CPU profiling, writing to the given file.
func (h *HandlerT) StartCPUProfile(file string) error {
h.mu.Lock()
defer h.mu.Unlock()
if h.cpuW != nil {
return errors.New("CPU profiling already in progress")
}
f, err := os.Create(expandHome(file))
if err != nil {
return err
}
if err := pprof.StartCPUProfile(f); err != nil {
f.Close()
return err
}
h.cpuW = f
h.cpuFile = file
glog.V(logger.Info).Infoln("CPU profiling started, writing to", h.cpuFile)
return nil
}
// StopCPUProfile stops an ongoing CPU profile.
func (h *HandlerT) StopCPUProfile() error {
h.mu.Lock()
defer h.mu.Unlock()
pprof.StopCPUProfile()
if h.cpuW == nil {
return errors.New("CPU profiling not in progress")
}
glog.V(logger.Info).Infoln("done writing CPU profile to", h.cpuFile)
h.cpuW.Close()
h.cpuW = nil
h.cpuFile = ""
return nil
}
// Trace turns on tracing for nsec seconds and writes
// trace data to file.
func (h *HandlerT) Trace(file string, nsec uint) error {
if err := h.StartTrace(file); err != nil {
return err
}
time.Sleep(time.Duration(nsec) * time.Second)
h.StopTrace()
return nil
}
// BlockProfile turns on CPU profiling for nsec seconds and writes
// profile data to file. It uses a profile rate of 1 for most accurate
// information. If a different rate is desired, set the rate
// and write the profile manually.
func (*HandlerT) BlockProfile(file string, nsec uint) error {
runtime.SetBlockProfileRate(1)
time.Sleep(time.Duration(nsec) * time.Second)
defer runtime.SetBlockProfileRate(0)
return writeProfile("block", file)
}
// SetBlockProfileRate sets the rate of goroutine block profile data collection.
// rate 0 disables block profiling.
func (*HandlerT) SetBlockProfileRate(rate int) {
runtime.SetBlockProfileRate(rate)
}
// WriteBlockProfile writes a goroutine blocking profile to the given file.
func (*HandlerT) WriteBlockProfile(file string) error {
return writeProfile("block", file)
}
// WriteMemProfile writes an allocation profile to the given file.
// Note that the profiling rate cannot be set through the API,
// it must be set on the command line.
func (*HandlerT) WriteMemProfile(file string) error {
return writeProfile("heap", file)
}
// Stacks returns a printed representation of the stacks of all goroutines.
func (*HandlerT) Stacks() string {
buf := make([]byte, 1024*1024)
buf = buf[:runtime.Stack(buf, true)]
return string(buf)
}
func writeProfile(name, file string) error {
p := pprof.Lookup(name)
glog.V(logger.Info).Infof("writing %d %s profile records to %s", p.Count(), name, file)
f, err := os.Create(expandHome(file))
if err != nil {
return err
}
defer f.Close()
return p.WriteTo(f, 0)
}
// expands home directory in file paths.
// ~someuser/tmp will not be expanded.
func expandHome(p string) string {
if strings.HasPrefix(p, "~/") || strings.HasPrefix(p, "~\\") {
home := os.Getenv("HOME")
if home == "" {
if usr, err := user.Current(); err == nil {
home = usr.HomeDir
}
}
if home != "" {
p = home + p[1:]
}
}
return filepath.Clean(p)
}

117
internal/debug/flags.go Normal file

@ -0,0 +1,117 @@
// Copyright 2016 The go-ethereum Authors
// This file is part of the go-ethereum library.
//
// The go-ethereum library is free software: you can redistribute it and/or modify
// it under the terms of the GNU Lesser General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// The go-ethereum library is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU Lesser General Public License for more details.
//
// You should have received a copy of the GNU Lesser General Public License
// along with the go-ethereum library. If not, see <http://www.gnu.org/licenses/>.
package debug
import (
"fmt"
"net/http"
_ "net/http/pprof"
"runtime"
"github.com/codegangsta/cli"
"github.com/ethereum/go-ethereum/logger"
"github.com/ethereum/go-ethereum/logger/glog"
)
var (
verbosityFlag = cli.GenericFlag{
Name: "verbosity",
Usage: "Logging verbosity: 0=silent, 1=error, 2=warn, 3=info, 4=core, 5=debug, 6=detail",
Value: glog.GetVerbosity(),
}
vmoduleFlag = cli.GenericFlag{
Name: "vmodule",
Usage: "Per-module verbosity: comma-separated list of <pattern>=<level> (e.g. eth/*=6,p2p=5)",
Value: glog.GetVModule(),
}
backtraceAtFlag = cli.GenericFlag{
Name: "backtrace",
Usage: "Request a stack trace at a specific logging statement (e.g. \"block.go:271\")",
Value: glog.GetTraceLocation(),
}
pprofFlag = cli.BoolFlag{
Name: "pprof",
Usage: "Enable the pprof HTTP server",
}
pprofPortFlag = cli.IntFlag{
Name: "pprofport",
Usage: "pprof HTTP server listening port",
Value: 6060,
}
memprofilerateFlag = cli.IntFlag{
Name: "memprofilerate",
Usage: "Turn on memory profiling with the given rate",
}
blockprofilerateFlag = cli.IntFlag{
Name: "blockprofilerate",
Usage: "Turn on block profiling with the given rate",
}
cpuprofileFlag = cli.StringFlag{
Name: "cpuprofile",
Usage: "Write CPU profile to the given file",
}
traceFlag = cli.StringFlag{
Name: "trace",
Usage: "Write execution trace to the given file",
}
)
// Flags holds all command-line flags required for debugging.
var Flags = []cli.Flag{
verbosityFlag, vmoduleFlag, backtraceAtFlag,
pprofFlag, pprofPortFlag,
memprofilerateFlag, blockprofilerateFlag, cpuprofileFlag, traceFlag,
}
// Setup initializes profiling and logging based on the CLI flags.
// It should be called as early as possible in the program.
func Setup(ctx *cli.Context) error {
// logging
glog.CopyStandardLogTo("INFO")
glog.SetToStderr(true)
// profiling, tracing
runtime.MemProfileRate = ctx.GlobalInt(memprofilerateFlag.Name)
Handler.SetBlockProfileRate(ctx.GlobalInt(blockprofilerateFlag.Name))
if traceFile := ctx.GlobalString(traceFlag.Name); traceFile != "" {
if err := Handler.StartTrace(traceFile); err != nil {
return err
}
}
if cpuFile := ctx.GlobalString(cpuprofileFlag.Name); cpuFile != "" {
if err := Handler.StartCPUProfile(cpuFile); err != nil {
return err
}
}
// pprof server
if ctx.GlobalBool(pprofFlag.Name) {
address := fmt.Sprintf("127.0.0.1:%d", ctx.GlobalInt(pprofPortFlag.Name))
go func() {
glog.V(logger.Info).Infof("starting pprof server at http://%s/debug/pprof", address)
glog.Errorln(http.ListenAndServe(address, nil))
}()
}
return nil
}
// Exit stops all running profiles, flushing their output to the
// respective file.
func Exit() {
Handler.StopCPUProfile()
Handler.StopTrace()
}

64
internal/debug/trace.go Normal file

@ -0,0 +1,64 @@
// Copyright 2016 The go-ethereum Authors
// This file is part of the go-ethereum library.
//
// The go-ethereum library is free software: you can redistribute it and/or modify
// it under the terms of the GNU Lesser General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// The go-ethereum library is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU Lesser General Public License for more details.
//
// You should have received a copy of the GNU Lesser General Public License
// along with the go-ethereum library. If not, see <http://www.gnu.org/licenses/>.
//+build go1.5
package debug
import (
"errors"
"os"
"runtime/trace"
"github.com/ethereum/go-ethereum/logger"
"github.com/ethereum/go-ethereum/logger/glog"
)
// StartTrace turns on tracing, writing to the given file.
func (h *HandlerT) StartTrace(file string) error {
h.mu.Lock()
defer h.mu.Unlock()
if h.traceW != nil {
return errors.New("trace already in progress")
}
f, err := os.Create(expandHome(file))
if err != nil {
return err
}
if err := trace.Start(f); err != nil {
f.Close()
return err
}
h.traceW = f
h.traceFile = file
glog.V(logger.Info).Infoln("trace started, writing to", h.traceFile)
return nil
}
// StopTrace stops an ongoing trace.
func (h *HandlerT) StopTrace() error {
h.mu.Lock()
defer h.mu.Unlock()
trace.Stop()
if h.traceW == nil {
return errors.New("trace not in progress")
}
glog.V(logger.Info).Infoln("done writing trace to", h.traceFile)
h.traceW.Close()
h.traceW = nil
h.traceFile = ""
return nil
}

@ -0,0 +1,31 @@
// Copyright 2016 The go-ethereum Authors
// This file is part of the go-ethereum library.
//
// The go-ethereum library is free software: you can redistribute it and/or modify
// it under the terms of the GNU Lesser General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// The go-ethereum library is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU Lesser General Public License for more details.
//
// You should have received a copy of the GNU Lesser General Public License
// along with the go-ethereum library. If not, see <http://www.gnu.org/licenses/>.
//+build !go1.5
// no-op implementation of tracing methods for Go < 1.5.
package debug
import "errors"
func (*HandlerT) StartTrace(string) error {
return errors.New("tracing is not supported on Go < 1.5")
}
func (*HandlerT) StopTrace() error {
return errors.New("tracing is not supported on Go < 1.5")
}

@ -23,7 +23,6 @@ import (
"github.com/ethereum/go-ethereum/common"
"github.com/ethereum/go-ethereum/crypto"
"github.com/ethereum/go-ethereum/logger/glog"
"github.com/ethereum/go-ethereum/p2p"
"github.com/ethereum/go-ethereum/p2p/discover"
"github.com/ethereum/go-ethereum/rpc"
@ -100,7 +99,6 @@ func (api *PrivateAdminAPI) StopRPC() (bool, error) {
return err == nil, err
}
// StartWS starts the websocket RPC API server.
func (api *PrivateAdminAPI) StartWS(address string, port int, cors string, apis string) (bool, error) {
var offeredAPIs []rpc.API
@ -179,30 +177,6 @@ func (api *PublicAdminAPI) Datadir() string {
return api.node.DataDir()
}
// PrivateDebugAPI is the collection of debugging related API methods exposed
// only over a secure RPC channel.
type PrivateDebugAPI struct {
node *Node // Node interfaced by this API
}
// NewPrivateDebugAPI creates a new API definition for the private debug methods
// of the node itself.
func NewPrivateDebugAPI(node *Node) *PrivateDebugAPI {
return &PrivateDebugAPI{node: node}
}
// Verbosity updates the node's logging verbosity. Note, due to the lack of fine
// grained contextual loggers, this will update the verbosity level for the entire
// process, not just this node instance.
func (api *PrivateDebugAPI) Verbosity(level int) {
glog.SetV(level)
}
// Vmodule updates the node's logging verbosity pattern.
func (api *PrivateDebugAPI) Vmodule(pattern string) error {
return glog.SetVmodule(pattern)
}
// PublicDebugAPI is the collection of debugging related API methods exposed over
// both secure and unsecure RPC channels.
type PublicDebugAPI struct {

@ -26,6 +26,7 @@ import (
"syscall"
"github.com/ethereum/go-ethereum/event"
"github.com/ethereum/go-ethereum/internal/debug"
"github.com/ethereum/go-ethereum/p2p"
"github.com/ethereum/go-ethereum/rpc"
)
@ -284,7 +285,7 @@ func (n *Node) APIs() []rpc.API {
}, {
Namespace: "debug",
Version: "1.0",
Service: NewPrivateDebugAPI(n),
Service: debug.Handler,
}, {
Namespace: "debug",
Version: "1.0",

@ -327,7 +327,78 @@ web3._extend({
name: 'metrics',
call: 'debug_metrics',
params: 1
})
}),
new web3._extend.Method({
name: 'verbosity',
call: 'debug_verbosity',
params: 1
}),
new web3._extend.Method({
name: 'vmodule',
call: 'debug_vmodule',
params: 1
}),
new web3._extend.Method({
name: 'backtraceAt',
call: 'debug_backtraceAt',
params: 1,
}),
new web3._extend.Method({
name: 'stacks',
call: 'debug_stacks',
params: 0,
outputFormatter: console.log
}),
new web3._extend.Method({
name: 'cpuProfile',
call: 'debug_cpuProfile',
params: 2
}),
new web3._extend.Method({
name: 'startCPUProfile',
call: 'debug_startCPUProfile',
params: 1
}),
new web3._extend.Method({
name: 'stopCPUProfile',
call: 'debug_stopCPUProfile',
params: 0
}),
new web3._extend.Method({
name: 'trace',
call: 'debug_trace',
params: 2
}),
new web3._extend.Method({
name: 'startTrace',
call: 'debug_startTrace',
params: 1
}),
new web3._extend.Method({
name: 'stopTrace',
call: 'debug_stopTrace',
params: 0
}),
new web3._extend.Method({
name: 'blockProfile',
call: 'debug_blockProfile',
params: 2
}),
new web3._extend.Method({
name: 'setBlockProfileRate',
call: 'debug_setBlockProfileRate',
params: 1
}),
new web3._extend.Method({
name: 'writeBlockProfile',
call: 'debug_writeBlockProfile',
params: 1
}),
new web3._extend.Method({
name: 'writeMemProfile',
call: 'debug_writeMemProfile',
params: 1
}),
],
properties:
[