11# Table of Contents
221 . [ Overview] ( #overview )
331 . [ Debug Logging] ( #debug-logging )
4- 1 . [ Capturing pprof data with ` lnd ` ] ( #capturing-pprof-data-with -lnd )
4+ 1 . [ LND's built-in profiler ] ( #built-in-profiler-in -lnd )
55
66## Overview
77
@@ -12,36 +12,192 @@ data ahead of time.
1212
1313## Debug Logging
1414
15- You can enable debug logging in ` lnd ` by passing the ` --debuglevel ` flag. For
16- example, to increase the log level from ` info ` to ` debug ` :
15+ LND supports different logging levels and you can also specify different logging
16+ levels per subsystem. This makes it easy to focus on a particular subsystem
17+ without clogging up the logs with a lot of noise. One can either set the logging
18+ in the lnd.conf file or pass the flag ` --debuglevel ` with the specified level
19+ when starting lnd.
20+
21+ LND supports the following logging levels (see [ log.go] ( /build/log.go ) and
22+ [ sample-lnd.conf] ( /sample-lnd.conf ) for more info):
23+
24+ - ` trace `
25+ - ` debug `
26+ - ` info `
27+ - ` warn `
28+ - ` error `
29+ - ` critical `
30+ - ` off `
31+
32+ LND is composed of many subsystems, those subsystems can be listed either by
33+ setting the starting flag ` --debuglevel ` or by using the lncli program.
34+
35+ Show all subsystems:
1736
1837``` shell
19- $ lnd --debuglevel=debug
38+ $ lnd --debuglevel=show
39+ $ lncli debuglevel --show
2040```
41+ For more details see [ log.go] ( /log.go ) .
2142
2243You may also specify logging per-subsystem, like this:
2344
2445``` shell
2546$ lnd --debuglevel=< subsystem> =< level> ,< subsystem2> =< level> ,...
47+ $ lncli debuglevel --level=< subsystem> =< level> ,< subsystem2> =< level> ,...
48+ ```
49+ The default global logging level is ` info ` . So if one wants to change the
50+ global logging level and in addition also set a more detailed logging for a
51+ particular subsystem the command would look like this (using ` HSWC `
52+ (htlcswitch) as an example subsystem):
53+
54+ ``` shell
55+ $ lnd --debuglevel=critical,HSWC=debug
56+ $ lncli debuglevel --level=critical,HSWC=debug
57+ ```
58+ The subsystem names are case-sensitive and must be all uppercase.
59+
60+ To identify the subsystems defined by an abbreviated name, you can search for
61+ the abbreviation in the [ log.go] ( /log.go ) file. Each subsystem
62+ declares a ` btclog.Logger ` instance locally which is then assigned via the
63+ ` UseLogger ` function call in the ` SetupLoggers ` function.
64+
65+ Example HSWC:
66+
67+ For the ` HSWC ` subsystem a new sublogger is injected into the htlcswitch
68+ package via the ` UseLogger ` function call in the ` SetupLoggers ` function. So
69+ the HSWC subsystem handles the logging in the htlcswitch package.
70+
71+ ``` go
72+ AddSubLogger (root, " HSWC" , interceptor, htlcswitch.UseLogger )
73+ ```
74+
75+ Caution: Some logger subsystems are overwritten during the instanziation. An
76+ example here is the ` neutrino/query ` package which instead of using the ` BTCN `
77+ prefix is overwritten by the ` LNWL ` subsystem.
78+
79+ Moreover when using the ` lncli ` command the return value will provide the
80+ updated list of all subsystems and their associated logging levels. This makes
81+ it easy to get an overview of the corrent logging level for the whole system.
82+
83+ Example:
84+
85+ ``` shell
86+ $ lncli debuglevel --level=critical,HSWC=debug
87+ {
88+ " 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"
89+ }
2690```
2791
28- ## Capturing pprof data with ` lnd `
2992
30- ` lnd ` has a built-in feature which allows you to capture profiling data at
93+ ## Built-in profiler in LND
94+
95+ ` LND ` has a built-in feature which allows you to capture profiling data at
3196runtime using [ pprof] ( https://golang.org/pkg/runtime/pprof/ ) , a profiler for
32- Go. The profiler has negligible performance overhead during normal operations
33- (unless you have explicitly enabled CPU profiling).
97+ Go. It is recommended to enable the profiling server so that an analyis can be
98+ triggered during runtime. There is only little overhead in enabling this
99+ feature, because profiling is only started when calling the server endpoints.
100+ However LND also allows to specify a cpu profile file via the ` cpuprofile ` flag
101+ which triggers a cpu profile when LND starts and stops it when LND shuts down.
102+ This is only recommended for debugging purposes, because the overhead is much
103+ higher. To enable the profile server, start ` lnd ` with the ` --profile ` option
104+ using a free port. As soon as the server is up different profiles can be
105+ fetched from the ` debug/pprof ` endpoint using either the web interface or for
106+ example ` curl ` .
34107
35- To enable this ability, start ` lnd ` with the ` -- profile` option using a free port .
108+ Example port ` 9736 ` is used for the profile server in the following examples .
36109
37110``` shell
38111$ lnd --profile=9736
39112```
40113
41- Now, with ` lnd ` running, you can use the pprof endpoint on port 9736 to collect
42- runtime profiling data. You can fetch this data using ` curl ` like so:
114+ NOTE: The ` --profile ` flag of the lncli program does not relate to profiling and
115+ the profiling server. It has a different context and allows a node operator to
116+ manage different LND daemons without providing all the cmd flags every time.
117+ For more details see [ lncli profile] ( /cmd/commands/profile.go ) .
118+
119+ ### Different types of profiles
120+
121+ #### CPU profile
122+
123+ A cpu profile can be used to analyze the CPU usage of the program. When
124+ obtaining it via the profile http endpoint you can specify the time duration as
125+ a query parameter.
126+
127+ ``` shell
128+ $ curl http://localhost:9736/debug/pprof/profile? seconds=10 > cpu.prof
129+ ```
130+ #### Goroutine profile
131+
132+ The goroutine profile is very useful when analyzing deadlocks and lock
133+ contention. It can be obtained via the web interface or the following endpoint:
134+
135+ ``` shell
136+ $ curl http://localhost:9736/debug/pprof/goroutine? debug=2 > goroutine.prof
137+ ```
138+ The query parameter ` debug=2 ` is optional but recommended and referes to the
139+ format of the output file. Only this format has the necessary information to
140+ identify goroutines deadlocks. Otherwise ` go tool pprof ` needs to be used to
141+ visualize the data and interpret the results.
142+
143+ #### Heap profile
144+
145+ The heap profile is useful to analyze memory allocations. It can be obtained
146+ via the following endpoint:
147+
148+ ``` shell
149+ $ curl http://localhost:9736/debug/pprof/heap > heap.prof
150+ ```
151+ The documentation of the pprof package states that a gc can be triggered before
152+ obtaining the heap profile. This can be done by setting the gc query parameter
153+ (` gc=1 ` ).
154+
155+ #### Other profiles
156+
157+ There are several other options available like a mutex profile or a block
158+ profile which gives insights into contention and bottlenecks of your program.
159+ The web interface lists all the available profiles/endpoints which can be
160+ obtained.
161+
162+ However mutex and block profiling need to be enabled separately by setting the
163+ sampling rate via the config values ` BlockingProfile ` and ` MutexProfile ` . They
164+ are off by default (0). These values represent sampling rates meaning that a
165+ value of ` 1 ` will record every event leading to a significant overhead whereas
166+ a sample rate of ` n ` will only record 1 out of nth events decreasing the
167+ aggressiveness of the profiler.
168+
169+ Fetching the block and mutex profile:
170+
171+ ``` shell
172+
173+ $ curl http://localhost:9736/debug/pprof/mutex? debug=2
174+
175+ $ curl http://localhost:9736/debug/pprof/block? debug=2
176+ ```
177+
178+ The full programm command can also be fetched which shows how LND was started
179+ and which flags were provided to the program.
180+
181+ ``` shell
182+ $ curl http://localhost:9736/debug/pprof/cmdline > cmdline.prof
183+ ```
184+
185+ There are also other endpoints available see the
186+ [ pprof documentation] ( https://golang.org/pkg/runtime/pprof/ ) for more details.
187+
188+
189+ #### Visualizing the profile dumps
190+
191+ It can be hard to make sense of the profile dumps by just looking at them
192+ therefore the Golang ecosystem provides tools to analyze those profile dumps
193+ either via the terminal or by visualizing them. One of the tools is
194+ ` go tool pprof ` .
195+
196+ Assuming the profile was fetched via ` curl ` as in the examples above a nice
197+ svg visualization can be generated for the cpu profile like this:
43198
44199``` shell
45- $ curl http://localhost:9736/debug/pprof/goroutine? debug=1
46- ...
200+ $ go tool pprof -svg cpu.prof > cpu.svg
47201```
202+ Details how to interpret these visualizations can be found in the
203+ [ pprof documentation] ( https://github.com/google/pprof/blob/main/doc/README.md#interpreting-the-callgraph ) .
0 commit comments