Skip to content

Commit

Permalink
Merge pull request lightningnetwork#9138 from ziggie1984/detail_debug…
Browse files Browse the repository at this point in the history
…_process

Detail LND's debug procedures.
yyforyongyu authored Oct 22, 2024
2 parents 91c82c1 + f73504a commit caff5a0
Showing 9 changed files with 409 additions and 90 deletions.
104 changes: 51 additions & 53 deletions config.go
Original file line number Diff line number Diff line change
@@ -352,12 +352,12 @@ type Config struct {

DebugLevel string `short:"d" long:"debuglevel" description:"Logging level for all subsystems {trace, debug, info, warn, error, critical} -- You may also specify <global-level>,<subsystem>=<level>,<subsystem2>=<level>,... to set the log level for individual subsystems -- Use show to list available subsystems"`

CPUProfile string `long:"cpuprofile" description:"Write CPU profile to the specified file"`
CPUProfile string `long:"cpuprofile" description:"DEPRECATED: Use 'pprof.cpuprofile' option. Write CPU profile to the specified file" hidden:"true"`
Profile string `long:"profile" description:"DEPRECATED: Use 'pprof.profile' option. Enable HTTP profiling on either a port or host:port" hidden:"true"`
BlockingProfile int `long:"blockingprofile" description:"DEPRECATED: Use 'pprof.blockingprofile' option. Used to enable a blocking profile to be served on the profiling port. This takes a value from 0 to 1, with 1 including every blocking event, and 0 including no events." hidden:"true"`
MutexProfile int `long:"mutexprofile" description:"DEPRECATED: Use 'pprof.mutexprofile' option. Used to Enable a mutex profile to be served on the profiling port. This takes a value from 0 to 1, with 1 including every mutex event, and 0 including no events." hidden:"true"`

Profile string `long:"profile" description:"Enable HTTP profiling on either a port or host:port"`

BlockingProfile int `long:"blockingprofile" description:"Used to enable a blocking profile to be served on the profiling port. This takes a value from 0 to 1, with 1 including every blocking event, and 0 including no events."`
MutexProfile int `long:"mutexprofile" description:"Used to Enable a mutex profile to be served on the profiling port. This takes a value from 0 to 1, with 1 including every mutex event, and 0 including no events."`
Pprof *lncfg.Pprof `group:"Pprof" namespace:"pprof"`

UnsafeDisconnect bool `long:"unsafe-disconnect" description:"DEPRECATED: Allows the rpcserver to intentionally disconnect from peers with open channels. THIS FLAG WILL BE REMOVED IN 0.10.0" hidden:"true"`
UnsafeReplay bool `long:"unsafe-replay" description:"Causes a link to replay the adds on its commitment txn after starting up, this enables testing of the sphinx replay logic."`
@@ -821,7 +821,8 @@ func LoadConfig(interceptor signal.Interceptor) (*Config, error) {
cleanCfg, err := ValidateConfig(
cfg, interceptor, fileParser, flagParser,
)
if usageErr, ok := err.(*usageError); ok {
var usageErr *lncfg.UsageError
if errors.As(err, &usageErr) {
// The logging system might not yet be initialized, so we also
// write to stderr to make sure the error appears somewhere.
_, _ = fmt.Fprintln(os.Stderr, usageMessage)
@@ -830,9 +831,9 @@ func LoadConfig(interceptor signal.Interceptor) (*Config, error) {
// The log subsystem might not yet be initialized. But we still
// try to log the error there since some packaging solutions
// might only look at the log and not stdout/stderr.
ltndLog.Warnf("Error validating config: %v", usageErr.err)
ltndLog.Warnf("Error validating config: %v", err)

return nil, usageErr.err
return nil, err
}
if err != nil {
// The log subsystem might not yet be initialized. But we still
@@ -856,18 +857,6 @@ func LoadConfig(interceptor signal.Interceptor) (*Config, error) {
return cleanCfg, nil
}

// usageError is an error type that signals a problem with the supplied flags.
type usageError struct {
err error
}

// Error returns the error string.
//
// NOTE: This is part of the error interface.
func (u *usageError) Error() string {
return u.err.Error()
}

// ValidateConfig check the given configuration to be sane. This makes sure no
// illegal values or combination of values are set. All file system paths are
// normalized. The cleaned up config is returned on success.
@@ -1347,31 +1336,6 @@ func ValidateConfig(cfg Config, interceptor signal.Interceptor, fileParser,
cfg.Autopilot.MaxChannelSize = int64(MaxFundingAmount)
}

// Validate profile port or host:port.
if cfg.Profile != "" {
str := "%s: The profile port must be between 1024 and 65535"

// Try to parse Profile as a host:port.
_, hostPort, err := net.SplitHostPort(cfg.Profile)
if err == nil {
// Determine if the port is valid.
profilePort, err := strconv.Atoi(hostPort)
if err != nil || profilePort < 1024 || profilePort > 65535 {
return nil, &usageError{mkErr(str)}
}
} else {
// Try to parse Profile as a port.
profilePort, err := strconv.Atoi(cfg.Profile)
if err != nil || profilePort < 1024 || profilePort > 65535 {
return nil, &usageError{mkErr(str)}
}

// Since the user just set a port, we will serve debugging
// information over localhost.
cfg.Profile = net.JoinHostPort("127.0.0.1", cfg.Profile)
}
}

// We'll now construct the network directory which will be where we
// store all the data specific to this chain/network.
cfg.networkDir = filepath.Join(
@@ -1442,20 +1406,20 @@ func ValidateConfig(cfg Config, interceptor signal.Interceptor, fileParser,
return nil, mkErr("log writer missing in config")
}

// Special show command to list supported subsystems and exit.
if cfg.DebugLevel == "show" {
fmt.Println("Supported subsystems",
cfg.LogWriter.SupportedSubsystems())
os.Exit(0)
}

if !build.SuportedLogCompressor(cfg.LogCompressor) {
return nil, mkErr("invalid log compressor: %v",
cfg.LogCompressor)
}

// Initialize logging at the default logging level.
SetupLoggers(cfg.LogWriter, interceptor)

// Special show command to list supported subsystems and exit.
if cfg.DebugLevel == "show" {
fmt.Println("Supported subsystems",
cfg.LogWriter.SupportedSubsystems())
os.Exit(0)
}
err = cfg.LogWriter.InitLogRotator(
filepath.Join(cfg.LogDir, defaultLogFilename),
cfg.LogCompressor, cfg.MaxLogFileSize, cfg.MaxLogFiles,
@@ -1469,7 +1433,7 @@ func ValidateConfig(cfg Config, interceptor signal.Interceptor, fileParser,
err = build.ParseAndSetDebugLevels(cfg.DebugLevel, cfg.LogWriter)
if err != nil {
str := "error parsing debug level: %v"
return nil, &usageError{mkErr(str, err)}
return nil, &lncfg.UsageError{Err: mkErr(str, err)}
}

// At least one RPCListener is required. So listen on localhost per
@@ -1700,6 +1664,39 @@ func ValidateConfig(cfg Config, interceptor signal.Interceptor, fileParser,
return nil, mkErr("custom-message: %v", err)
}

// Map old pprof flags to new pprof group flags.
//
// NOTE: This is a temporary measure to ensure compatibility with old
// flags.
if cfg.CPUProfile != "" {
if cfg.Pprof.CPUProfile != "" {
return nil, mkErr("cpuprofile and pprof.cpuprofile " +
"are mutually exclusive")
}
cfg.Pprof.CPUProfile = cfg.CPUProfile
}
if cfg.Profile != "" {
if cfg.Pprof.Profile != "" {
return nil, mkErr("profile and pprof.profile " +
"are mutually exclusive")
}
cfg.Pprof.Profile = cfg.Profile
}
if cfg.BlockingProfile != 0 {
if cfg.Pprof.BlockingProfile != 0 {
return nil, mkErr("blockingprofile and " +
"pprof.blockingprofile are mutually exclusive")
}
cfg.Pprof.BlockingProfile = cfg.BlockingProfile
}
if cfg.MutexProfile != 0 {
if cfg.Pprof.MutexProfile != 0 {
return nil, mkErr("mutexprofile and " +
"pprof.mutexprofile are mutually exclusive")
}
cfg.Pprof.MutexProfile = cfg.MutexProfile
}

// Validate the subconfigs for workers, caches, and the tower client.
err = lncfg.Validate(
cfg.Workers,
@@ -1714,6 +1711,7 @@ func ValidateConfig(cfg Config, interceptor signal.Interceptor, fileParser,
cfg.Htlcswitch,
cfg.Invoices,
cfg.Routing,
cfg.Pprof,
)
if err != nil {
return nil, err
182 changes: 169 additions & 13 deletions docs/debugging_lnd.md
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
# Table of Contents
1. [Overview](#overview)
1. [Debug Logging](#debug-logging)
1. [Capturing pprof data with `lnd`](#capturing-pprof-data-with-lnd)
1. [LND's built-in profiler](#built-in-profiler-in-lnd)

## Overview

@@ -12,36 +12,192 @@ data ahead of time.

## Debug Logging

You can enable debug logging in `lnd` by passing the `--debuglevel` flag. For
example, to increase the log level from `info` to `debug`:
LND supports different logging levels and you can also specify different logging
levels per subsystem. This makes it easy to focus on a particular subsystem
without clogging up the logs with a lot of noise. One can either set the logging
in the lnd.conf file or pass the flag `--debuglevel` with the specified level
when starting lnd.

LND supports the following logging levels (see [log.go](/build/log.go) and
[sample-lnd.conf](/sample-lnd.conf) for more info):

- `trace`
- `debug`
- `info`
- `warn`
- `error`
- `critical`
- `off`

LND is composed of many subsystems, those subsystems can be listed either by
setting the starting flag `--debuglevel` or by using the lncli program.

Show all subsystems:

```shell
$ lnd --debuglevel=debug
$ lnd --debuglevel=show
$ lncli debuglevel --show
```
For more details see [log.go](/log.go).

You may also specify logging per-subsystem, like this:

```shell
$ lnd --debuglevel=<subsystem>=<level>,<subsystem2>=<level>,...
$ lncli debuglevel --level=<subsystem>=<level>,<subsystem2>=<level>,...
```
The default global logging level is `info`. So if one wants to change the
global logging level and in addition also set a more detailed logging for a
particular subsystem the command would look like this (using `HSWC`
(htlcswitch) as an example subsystem):

```shell
$ lnd --debuglevel=critical,HSWC=debug
$ lncli debuglevel --level=critical,HSWC=debug
```
The subsystem names are case-sensitive and must be all uppercase.

To identify the subsystems defined by an abbreviated name, you can search for
the abbreviation in the [log.go](/log.go) file. Each subsystem
declares a `btclog.Logger` instance locally which is then assigned via the
`UseLogger` function call in the `SetupLoggers` function.

Example HSWC:

For the `HSWC` subsystem a new sublogger is injected into the htlcswitch
package via the `UseLogger` function call in the `SetupLoggers` function. So
the HSWC subsystem handles the logging in the htlcswitch package.

```go
AddSubLogger(root, "HSWC", interceptor, htlcswitch.UseLogger)
```

Caution: Some logger subsystems are overwritten during the instanziation. An
example here is the `neutrino/query` package which instead of using the `BTCN`
prefix is overwritten by the `LNWL` subsystem.

Moreover when using the `lncli` command the return value will provide the
updated list of all subsystems and their associated logging levels. This makes
it easy to get an overview of the corrent logging level for the whole system.

Example:

```shell
$ lncli debuglevel --level=critical,HSWC=debug
{
"sub_systems": "ARPC=INF, ATPL=INF, BLPT=INF, BRAR=INF, BTCN=INF, BTWL=INF, CHAC=INF, CHBU=INF, CHCL=INF, CHDB=INF, CHFD=INF, CHFT=INF, CHNF=INF, CHRE=INF, CLUS=INF, CMGR=INF, CNCT=INF, CNFG=INF, CRTR=INF, DISC=INF, DRPC=INF, FNDG=INF, GRPH=INF, HLCK=INF, HSWC=DBG, INVC=INF, IRPC=INF, LNWL=INF, LTND=INF, NANN=INF, NRPC=INF, NTFN=INF, NTFR=INF, PEER=INF, PRNF=INF, PROM=INF, PRPC=INF, RPCP=INF, RPCS=INF, RPWL=INF, RRPC=INF, SGNR=INF, SPHX=INF, SRVR=INF, SWPR=INF, TORC=INF, UTXN=INF, VRPC=INF, WLKT=INF, WTCL=INF, WTWR=INF"
}
```

## Capturing pprof data with `lnd`

`lnd` has a built-in feature which allows you to capture profiling data at
## Built-in profiler in LND

`LND` has a built-in feature which allows you to capture profiling data at
runtime using [pprof](https://golang.org/pkg/runtime/pprof/), a profiler for
Go. The profiler has negligible performance overhead during normal operations
(unless you have explicitly enabled CPU profiling).
Go. It is recommended to enable the profiling server so that an analyis can be
triggered during runtime. There is only little overhead in enabling this
feature, because profiling is only started when calling the server endpoints.
However LND also allows to specify a cpu profile file via the `cpuprofile` flag
which triggers a cpu profile when LND starts and stops it when LND shuts down.
This is only recommended for debugging purposes, because the overhead is much
higher. To enable the profile server, start `lnd` with the `--profile` option
using a free port. As soon as the server is up different profiles can be
fetched from the `debug/pprof` endpoint using either the web interface or for
example `curl`.

To enable this ability, start `lnd` with the `--profile` option using a free port.
Example port `9736` is used for the profile server in the following examples.

```shell
$ lnd --profile=9736
```

Now, with `lnd` running, you can use the pprof endpoint on port 9736 to collect
runtime profiling data. You can fetch this data using `curl` like so:
NOTE: The `--profile` flag of the lncli program does not relate to profiling and
the profiling server. It has a different context and allows a node operator to
manage different LND daemons without providing all the cmd flags every time.
For more details see [lncli profile](/cmd/commands/profile.go).

### Different types of profiles

#### CPU profile

A cpu profile can be used to analyze the CPU usage of the program. When
obtaining it via the profile http endpoint you can specify the time duration as
a query parameter.

```shell
$ curl http://localhost:9736/debug/pprof/profile?seconds=10 > cpu.prof
```
#### Goroutine profile

The goroutine profile is very useful when analyzing deadlocks and lock
contention. It can be obtained via the web interface or the following endpoint:

```shell
$ curl http://localhost:9736/debug/pprof/goroutine?debug=2 > goroutine.prof
```
The query parameter `debug=2` is optional but recommended and referes to the
format of the output file. Only this format has the necessary information to
identify goroutines deadlocks. Otherwise `go tool pprof` needs to be used to
visualize the data and interpret the results.

#### Heap profile

The heap profile is useful to analyze memory allocations. It can be obtained
via the following endpoint:

```shell
$ curl http://localhost:9736/debug/pprof/heap > heap.prof
```
The documentation of the pprof package states that a gc can be triggered before
obtaining the heap profile. This can be done by setting the gc query parameter
(`gc=1`).

#### Other profiles

There are several other options available like a mutex profile or a block
profile which gives insights into contention and bottlenecks of your program.
The web interface lists all the available profiles/endpoints which can be
obtained.

However mutex and block profiling need to be enabled separately by setting the
sampling rate via the config values `BlockingProfile` and `MutexProfile`. They
are off by default (0). These values represent sampling rates meaning that a
value of `1` will record every event leading to a significant overhead whereas
a sample rate of `n` will only record 1 out of nth events decreasing the
aggressiveness of the profiler.

Fetching the block and mutex profile:

```shell

$ curl http://localhost:9736/debug/pprof/mutex?debug=2

$ curl http://localhost:9736/debug/pprof/block?debug=2
```

The full programm command can also be fetched which shows how LND was started
and which flags were provided to the program.

```shell
$ curl http://localhost:9736/debug/pprof/cmdline > cmdline.prof
```

There are also other endpoints available see the
[pprof documentation](https://golang.org/pkg/runtime/pprof/) for more details.


#### Visualizing the profile dumps

It can be hard to make sense of the profile dumps by just looking at them
therefore the Golang ecosystem provides tools to analyze those profile dumps
either via the terminal or by visualizing them. One of the tools is
`go tool pprof`.

Assuming the profile was fetched via `curl` as in the examples above a nice
svg visualization can be generated for the cpu profile like this:

```shell
$ curl http://localhost:9736/debug/pprof/goroutine?debug=1
...
$ go tool pprof -svg cpu.prof > cpu.svg
```
Details how to interpret these visualizations can be found in the
[pprof documentation](https://github.com/google/pprof/blob/main/doc/README.md#interpreting-the-callgraph).
Loading

0 comments on commit caff5a0

Please sign in to comment.