emacs.d/clones/lispcookbook.github.io/cl-cookbook/debugging.html

561 lines
20 KiB
HTML
Raw Normal View History

2022-08-02 12:34:59 +02:00
<!DOCTYPE html>
<html lang="en">
<head>
<meta name="generator" content=
"HTML Tidy for HTML5 for Linux version 5.2.0">
<title>Debugging</title>
<meta charset="utf-8">
<meta name="description" content="A collection of examples of using Common Lisp">
<meta name="viewport" content=
"width=device-width, initial-scale=1">
<link rel="stylesheet" href=
"assets/style.css">
<script type="text/javascript" src=
"assets/highlight-lisp.js">
</script>
<script type="text/javascript" src=
"assets/jquery-3.2.1.min.js">
</script>
<script type="text/javascript" src=
"assets/jquery.toc/jquery.toc.min.js">
</script>
<script type="text/javascript" src=
"assets/toggle-toc.js">
</script>
<link rel="stylesheet" href=
"assets/github.css">
<link rel="stylesheet" href="https://maxcdn.bootstrapcdn.com/bootstrap/3.3.7/css/bootstrap.min.css" integrity="sha384-BVYiiSIFeK1dGmJRAkycuHAHRg32OmUcww7on3RYdg4Va+PmSTsz/K68vbdEjh4u" crossorigin="anonymous">
</head>
<body>
<h1 id="title-xs"><a href="index.html">The Common Lisp Cookbook</a> &ndash; Debugging</h1>
<div id="logo-container">
<a href="index.html">
<img id="logo" src="assets/cl-logo-blue.png"/>
</a>
<div id="searchform-container">
<form onsubmit="duckSearch()" action="javascript:void(0)">
<input id="searchField" type="text" value="" placeholder="Search...">
</form>
</div>
<div id="toc-container" class="toc-close">
<div id="toc-title">Table of Contents</div>
<ul id="toc" class="list-unstyled"></ul>
</div>
</div>
<div id="content-container">
<h1 id="title-non-xs"><a href="index.html">The Common Lisp Cookbook</a> &ndash; Debugging</h1>
<!-- Announcement we can keep for 1 month or more. I remove it and re-add it from time to time. -->
<p class="announce">
📹 <a href="https://www.udemy.com/course/common-lisp-programming/?couponCode=6926D599AA-LISP4ALL">NEW! Learn Lisp in videos and support our contributors with this 40% discount.</a>
</p>
<p class="announce-neutral">
📕 <a href="index.html#download-in-epub">Get the EPUB and PDF</a>
</p>
<div id="content"
<p>You entered this new world of Lisp and now wonder: how can we debug
whats going on? How is it more interactive than other platforms?
What does the interactive debugger bring, apart from stack traces?</p>
<h2 id="print-debugging">Print debugging</h2>
<p>Well of course we can use the famous technique of “print
debugging”. Lets just recap a few print functions.</p>
<p><code>print</code> works, it prints a <code>read</code>able representation of its argument,
which means what is <code>print</code>ed can be <code>read</code> back in by the Lisp
reader.</p>
<p><code>princ</code> focuses on an <em>aesthetic</em> representation.</p>
<p><code>(format t "~a" …)</code>, with the <em>aesthetic</em> directive, prints a string (in <code>t</code>, the standard output
stream) and returns nil, whereas <code>format nil …</code> doesnt print anything
and returns a string. With many format controls we can print several
variables at once.</p>
<h2 id="logging">Logging</h2>
<p>Logging is already a good evolution from print debugging ;)</p>
<p><a href="https://github.com/sharplispers/log4cl/">log4cl</a> is the popular,
de-facto logging library but it isnt the only one. Download it:</p>
<pre><code class="language-lisp">(ql:quickload "log4cl")
</code></pre>
<p>and lets have a dummy variable:</p>
<pre><code class="language-lisp">(defvar *foo* '(:a :b :c))
</code></pre>
<p>We can use log4cl with its <code>log</code> nickname, then it is as simple to use as:</p>
<pre><code class="language-lisp">(log:info *foo*)
;; &lt;INFO&gt; [13:36:49] cl-user () - *FOO*: (:A :B :C)
</code></pre>
<p>We can interleave strings and expressions, with or without <code>format</code>
control strings:</p>
<pre><code class="language-lisp">(log:info "foo is " *foo*)
;; &lt;INFO&gt; [13:37:22] cl-user () - foo is *FOO*: (:A :B :C)
(log:info "foo is ~{~a~}" *foo*)
;; &lt;INFO&gt; [13:39:05] cl-user () - foo is ABC
</code></pre>
<p>With its companion library <code>log4slime</code>, we can interactively change
the log level:</p>
<ul>
<li>globally</li>
<li>per package</li>
<li>per function</li>
<li>and by CLOS methods and CLOS hierarchy (before and after methods)</li>
</ul>
<p>It is very handy, when we have a lot of output, to turn off the
logging of functions or packages we know to work, and thus narrowing
our search to the right area. We can even save this configuration and
re-use it in another image, be it on another machine.</p>
<p>We can do all this through commands, keyboard shortcuts and also through a
menu or mouse clicks.</p>
<p><img src="assets/log4cl.png" alt="&quot;changing the log level with log4slime&quot;" /></p>
<p>We invite you to read log4cls README.</p>
<h2 id="using-the-powerful-repl">Using the powerful REPL</h2>
<p>Part of the joy of Lisp is the excellent REPL. Its existence usually
delays the need to use other debugging tools, if it doesnt annihilate
them for the usual routine.</p>
<p>As soon as we define a function, we can try it in the REPL. In Slime,
compile a function with <code>C-c C-c</code> (the whole buffer with <code>C-c C-k</code>),
switch to the REPL with <code>C-c C-z</code> and try it. Eventually enter the
package you are working on with <code>(in-package :your-package)</code>
or <code>C-c ~</code> (<code>slime-sync-package-and-default-directory</code>),
(which will also change the default working directory to the package definitions directory).</p>
<p>The feedback is immediate. There is no need to recompile everything,
nor to restart any process, nor to create a main function and define
command line arguments for use in the shell (which we can of course do later on
when needed).</p>
<p>We usually need to create some data to test our function(s). This is a
subsequent art of the REPL existence and it may be a new discipline
for newcomers. A trick is to write the test data alongside your
functions but below a <code>#+nil</code> feature test (or safer, <code>+(or nil)</code>) so that only you can
manually compile them:</p>
<pre><code class="language-lisp">#+nil
(progn
(defvar *test-data* nil)
(setf *test-data* (make-instance 'foo …)))
</code></pre>
<p>When you load this file, <code>*test-data*</code> wont exist, but you can
manually create it with <code>C-c C-c</code>.</p>
<p>We can define tests functions like this.</p>
<p>Some do similarly inside <code>#| … |#</code> comments.</p>
<p>All that being said, keep in mind to write unit tests when time comes ;)</p>
<h2 id="inspect-and-describe">Inspect and describe</h2>
<p>These two commands share the same goal, printing a description of an
object, <code>inspect</code> being the interactive one.</p>
<pre><code>(inspect *foo*)
The object is a proper list of length 3.
0. 0: :A
1. 1: :B
2. 2: :C
&gt; q
</code></pre>
<p>We can also, in editors that support it, right-click on any object in
the REPL and <code>inspect</code> them. We are presented a screen where we can
dive deep inside the data structure and even change it.</p>
<p>Lets have a quick look with a more interesting structure, an object:</p>
<pre><code class="language-lisp">(defclass foo ()
((a :accessor foo-a :initform '(:a :b :c))
(b :accessor foo-b :initform :b)))
;; #&lt;STANDARD-CLASS FOO&gt;
(make-instance 'foo)
;; #&lt;FOO {100F2B6183}&gt;
</code></pre>
<p>We right-click on the <code>#&lt;FOO</code> object and choose “inspect”. We are
presented an interactive pane (in Slime):</p>
<pre><code>#&lt;FOO {100F2B6183}&gt;
--------------------
Class: #&lt;STANDARD-CLASS FOO&gt;
--------------------
Group slots by inheritance [ ]
Sort slots alphabetically [X]
All Slots:
[ ] A = (:A :B :C)
[ ] B = :B
[set value] [make unbound]
</code></pre>
<p>When we click or press enter on the line of slot A, we inspect it further:</p>
<pre><code>#&lt;CONS {100F5E2A07}&gt;
--------------------
A proper list:
0: :A
1: :B
2: :C
</code></pre>
<h2 id="the-interactive-debugger">The interactive debugger</h2>
<p>Whenever an exceptional situation happens (see
<a href="error_handling.html">error handling</a>), the interactive debugger pops
up.</p>
<p>It presents the error message, available actions (<em>restarts</em>),
and the backtrace. A few remarks:</p>
<ul>
<li>the restarts are programmable, we can create our own</li>
<li>in Slime, press <code>v</code> on a stack trace frame to view the corresponding
source file location</li>
<li>hit enter on a frame for more details</li>
<li>we can explore the functionality with the menu that should appear
in our editor. See the “break” section below for a few
more commands (eval in frame, etc).</li>
</ul>
<h3 id="compile-with-maximum-debugging-information">Compile with maximum debugging information</h3>
<p>Usually your compiler will optimize things out and this will reduce
the amount of information available to the debugger. For example
sometimes we cant see intermediate variables of computations. We can
change the optimization choices with:</p>
<pre><code class="language-lisp">(declaim (optimize (speed 0) (space 0) (debug 3)))
</code></pre>
<p>and recompile our code. You can achieve the same with a handy shortcut: <code>C-u C-c C-c</code>: the form is compiled with maximum debug settings. You can on the contrary use a negative prefix argument (<code>M--</code>) to compile for speed. And use a numeric argument to set the setting to it (you should read the docstring of <code>slime-compile-defun</code>).</p>
<h2 id="trace">Trace</h2>
<p><a href="http://www.xach.com/clhs?q=trace">trace</a> allows us to see when a
function was called, what arguments it received, and the value it
returned.</p>
<pre><code class="language-lisp">(defun factorial (n)
(if (plusp n)
(* n (factorial (1- n)))
1))
</code></pre>
<pre><code class="language-lisp">(trace factorial)
(factorial 2)
0: (FACTORIAL 3)
1: (FACTORIAL 2)
2: (FACTORIAL 1)
3: (FACTORIAL 0)
3: FACTORIAL returned 1
2: FACTORIAL returned 1
1: FACTORIAL returned 2
0: FACTORIAL returned 6
6
(untrace factorial)
</code></pre>
<p>To untrace all functions, just evaluate <code>(untrace)</code>.</p>
<p>In Slime we also have the shortcut <code>C-c M-t</code> to trace or untrace a
function.</p>
<p>If you dont see recursive calls, that may be because of the
compilers optimizations. Try this before defining the function to be
traced:</p>
<pre><code class="language-lisp">(declaim (optimize (debug 3)))
</code></pre>
<p>The output is printed to <code>*trace-output*</code> (see the CLHS).</p>
<p>In Slime, we also have an interactive trace dialog with <code>M-x
slime-trace-dialog</code> bound to <code>C-c T</code>.</p>
<h3 id="tracing-method-invocation">Tracing method invocation</h3>
<p>In SBCL, we can use <code>(trace foo :methods t)</code> to trace the execution order of method combination (before, after, around methods). For example:</p>
<pre><code class="language-lisp">(trace foo :methods t)
(foo 2.0d0)
0: (FOO 2.0d0)
1: ((SB-PCL::COMBINED-METHOD FOO) 2.0d0)
2: ((METHOD FOO (FLOAT)) 2.0d0)
3: ((METHOD FOO (T)) 2.0d0)
3: (METHOD FOO (T)) returned 3
2: (METHOD FOO (FLOAT)) returned 9
2: ((METHOD FOO :AFTER (DOUBLE-FLOAT)) 2.0d0)
2: (METHOD FOO :AFTER (DOUBLE-FLOAT)) returned DOUBLE
1: (SB-PCL::COMBINED-METHOD FOO) returned 9
0: FOO returned 9
9
</code></pre>
<p>See the <a href="clos.html">CLOS</a> section for a tad more information.</p>
<h2 id="step">Step</h2>
<p><a href="http://www.xach.com/clhs?q=step">step</a> is an interactive command with
similar scope than <code>trace</code>. This:</p>
<pre><code class="language-lisp">(step (factorial 2))
</code></pre>
<p>gives an interactive pane with the available restarts:</p>
<pre><code>Evaluating call:
(FACTORIAL 2)
With arguments:
2
[Condition of type SB-EXT:STEP-FORM-CONDITION]
Restarts:
0: [STEP-CONTINUE] Resume normal execution
1: [STEP-OUT] Resume stepping after returning from this function
2: [STEP-NEXT] Step over call
3: [STEP-INTO] Step into call
4: [RETRY] Retry SLIME REPL evaluation request.
5: [*ABORT] Return to SLIME's top level.
--more--
Backtrace:
0: ((LAMBDA ()))
1: (SB-INT:SIMPLE-EVAL-IN-LEXENV (LET ((SB-IMPL::*STEP-OUT* :MAYBE)) (UNWIND-PROTECT (SB-IMPL::WITH-STEPPING-ENABLED #))) #S(SB-KERNEL:LEXENV :FUNS NIL :VARS NIL :BLOCKS NIL :TAGS NIL :TYPE-RESTRICTIONS ..
2: (SB-INT:SIMPLE-EVAL-IN-LEXENV (STEP (FACTORIAL 2)) #&lt;NULL-LEXENV&gt;)
3: (EVAL (STEP (FACTORIAL 2)))
</code></pre>
<p>Stepping is useful, however it may be a sign that you need to simplify your function.</p>
<h2 id="break">Break</h2>
<p>A call to <a href="http://www.xach.com/clhs?q=break">break</a> makes the program
enter the debugger, from which we can inspect the call stack.</p>
<h3 id="breakpoints-in-slime">Breakpoints in Slime</h3>
<p>Look at the <code>SLDB</code> menu, it shows navigation keys and available
actions. Of which:</p>
<ul>
<li><code>e</code> (<em>sldb-eval-in-frame</em>) prompts for an expression and evaluates
it in the selected frame. This is how we can explore our
intermediate variables</li>
<li><code>d</code> is similar with the addition of pretty printing the result</li>
</ul>
<p>Once we are in a frame and detect a suspicious behavior, we can even
re-compile a function at runtime and resume the program execution from
where it stopped (using the “step-continue” restart).</p>
<h2 id="advise-and-watch">Advise and watch</h2>
<p><em>advise</em> and
<a href="http://www.xach.com/clhs?q=watch">watch</a> are available in some
implementations, like CCL
(<a href="https://ccl.clozure.com/manual/chapter4.3.html#Advising">advise</a> and
<a href="https://ccl.clozure.com/manual/chapter4.12.html#watched-objects">watch</a>)
and <a href="http://www.lispworks.com/">LispWorks</a>. They do exist in
SBCL but are not exported. <code>advise</code> allows to modify a function without changing its
source, or to do something before or after its execution, similar
to CLOS method combination (before, after, around methods).</p>
<p><code>watch</code> will signal a condition when a thread attempts to write to an
object being watched. It can be coupled with the display of the
watched objects in a GUI.
For a certain class of bugs (someone is changing this value, but I
dont know who), this can be extremely helpful.</p>
<h2 id="unit-tests">Unit tests</h2>
<p>Last but not least, automatic testing of functions in isolation might
be what youre looking for! See the <a href="testing.html">testing</a> section and a list of
<a href="https://github.com/CodyReichert/awesome-cl#unit-testing">test frameworks and libraries</a>.</p>
<h2 id="remote-debugging">Remote debugging</h2>
<p>You can have your software running on a machine over the network,
connect to it and debug it from home, from your development
environment.</p>
<p>The steps involved are to start a <strong>Swank server</strong> on the remote machine (Swank is the backend companion of Slime), create an
ssh tunnel and connect to the Swank server from our editor. Then we
can browse and evaluate code on the running instance transparently.</p>
<p>To test this, lets define a function that prints forever.</p>
<p>If needed, import the dependencies first:</p>
<pre><code class="language-lisp">(ql:quickload '("swank" "bordeaux-threads"))
</code></pre>
<pre><code class="language-lisp">;; a little common lisp swank demo
;; while this program is running, you can connect to it from another terminal or machine
;; and change the definition of doprint to print something else out!
(require :swank)
(require :bordeaux-threads)
(defparameter *counter* 0)
(defun dostuff ()
(format t "hello world ~a!~%" *counter*))
(defun runner ()
(swank:create-server :port 4006)
(format t "we are past go!~%")
(bt:make-thread (lambda ()
(loop repeat 5 do
(sleep 5)
(dostuff)
(incf *counter*)))
:name "do-stuff"))
(runner)
</code></pre>
<p>On the server, we can run this code with</p>
<pre><code>sbcl --load demo.lisp
</code></pre>
<p>If you check with <code>(bt:all-threads)</code>, youll see your Swank server running on port 4006, as well
as the other thread ready to do stuff:</p>
<pre><code>(#&lt;SB-THREAD:THREAD "do-stuff" RUNNING {10027CEDC3}&gt;
#&lt;SB-THREAD:THREAD "Swank Sentinel" waiting on:
#&lt;WAITQUEUE {10027D0003}&gt;
{10027CE8B3}&gt;
#&lt;SB-THREAD:THREAD "Swank 4006" RUNNING {10027CEB63}&gt;
#&lt;SB-THREAD:THREAD "main thread" RUNNING {1007C40393}&gt;)
</code></pre>
<p>We do port forwarding on our development machine:</p>
<pre><code>ssh -L4006:127.0.0.1:4006 username@example.com
</code></pre>
<p>this will securely forward port 4006 on the server at example.com to
our local computers port 4006 (Swank only accepts connections from
localhost).</p>
<p>We connect to the running Swank with <code>M-x slime-connect</code>, choosing localhost for the host
and port 4006.</p>
<p>We can write new code:</p>
<pre><code class="language-lisp">(defun dostuff ()
(format t "goodbye world ~a!~%" *counter*))
(setf *counter* 0)
</code></pre>
<p>and eval it as usual with <code>C-c C-c</code> or <code>M-x slime-eval-region</code> for instance. The output should change.</p>
<p>Thats how Ron Garret debugged the Deep Space 1 spacecraft from the earth
in 1999:</p>
<blockquote>
<p>We were able to debug and fix a race condition that had not shown up during ground testing. (Debugging a program running on a $100M piece of hardware that is 100 million miles away is an interesting experience. Having a read-eval-print loop running on the spacecraft proved invaluable in finding and fixing the problem.</p>
</blockquote>
<h2 id="references">References</h2>
<ul>
<li><a href="https://successful-lisp.blogspot.com/p/httpsdrive.html">“How to understand and use Common Lisp”</a>, chap. 30, David Lamkins (book download from authors site)</li>
<li><a href="https://malisper.me/debugging-lisp-part-1-recompilation/">Malisper: debugging Lisp series</a></li>
<li><a href="https://two-wrongs.com/debugging-common-lisp-in-slime.html">Two Wrongs: debugging Common Lisp in Slime</a></li>
<li><a href="https://common-lisp.net/project/slime/doc/html/Connecting-to-a-remote-lisp.html#Connecting-to-a-remote-lisp">Slime documentation: connecting to a remote Lisp</a></li>
<li><a href="http://cvberry.com/tech_writings/howtos/remotely_modifying_a_running_program_using_swank.html">cvberrycom: remotely modifying a running Lisp program using Swank</a></li>
<li><a href="http://www.flownet.com/gat/jpl-lisp.html#1994-1999%20-%20Remote%20Agent">Ron Garret: Lisping at the JPL</a></li>
<li><a href="https://www.youtube.com/watch?v=_gZK0tW8EhQ&amp;feature=youtu.be&amp;t=4175">the Remote Agent experiment: debugging code from 60 million miles away (youtube)</a> (<a href="https://www.reddit.com/r/lisp/comments/a7156w/lisp_and_the_remote_agent/">“AMA” on reddit</a>)</li>
</ul>
<p class="page-source">
Page source: <a href="https://github.com/LispCookbook/cl-cookbook/blob/master/debugging.md">debugging.md</a>
</p>
</div>
<script type="text/javascript">
// Don't write the TOC on the index.
if (window.location.pathname != "/cl-cookbook/") {
$("#toc").toc({
content: "#content", // will ignore the first h1 with the site+page title.
headings: "h1,h2,h3,h4"});
}
$("#two-cols + ul").css({
"column-count": "2",
});
$("#contributors + ul").css({
"column-count": "4",
});
</script>
<div>
<footer class="footer">
<hr/>
&copy; 2002&ndash;2021 the Common Lisp Cookbook Project
</footer>
</div>
<div id="toc-btn">T<br>O<br>C</div>
</div>
<script text="javascript">
HighlightLisp.highlight_auto({className: null});
</script>
<script type="text/javascript">
function duckSearch() {
var searchField = document.getElementById("searchField");
if (searchField && searchField.value) {
var query = escape("site:lispcookbook.github.io/cl-cookbook/ " + searchField.value);
window.location.href = "https://duckduckgo.com/?kj=b2&kf=-1&ko=1&q=" + query;
// https://duckduckgo.com/params
// kj=b2: blue header in results page
// kf=-1: no favicons
}
}
</script>
<script async defer data-domain="lispcookbook.github.io/cl-cookbook" src="https://plausible.io/js/plausible.js"></script>
</body>
</html>