Repository files navigation

A Clojure(Script) library designed to make it easy to debug single- and multi-threaded applications.

Add[spyscope "0.1.6"] to your project.clj's:dependencies.

If you want spyscope to be automatically loaded and available in every project,add the following to the:user profile in~/.lein/profiles.clj:

:dependencies [[spyscope "0.1.6"]]:injections [(require 'spyscope.core)]

After requiring the namespace, you must also run(boot.core/load-data-readers!)to get the reader tags working. Using a~/.boot/profile.boot file:

(set-env! :dependencies #(conj % '[spyscope "0.1.6"]))(require 'spyscope.core)(boot.core/load-data-readers!)

Spyscope includes 3 reader tools for debugging your Clojure code, which are exposed as reader tags:#spy/p,#spy/d, and#spy/t, which stand forprint,details, andtrace, respectively.Reader tags were chosen because they allow one to use Spyscope by only writing 6 characters, andsince they exist only to the left of the form one wants to debug, they require the fewest possiblekeystrokes, optimizing for developer happiness. :)

First, let's look at#spy/p, which just pretty-prints the form of interest:

spyscope.repl=> (take20 (repeat #spy/p (+123)))6(66666666666666666666)

#spy/p is an extremely simple tool that merely saves a few keystores whenone needs to dump out a value in the middle of a calculation.

Next, let's look at#spy/d. This is where the real power lies:

spyscope.repl=> (take20 (repeat #spy/d (+123)))spyscope.repl$eval3869.invoke(NO_SOURCE_FILE:1) (+123) =>6(66666666666666666666)

In the simplest usage, the form is printed along with the stack traceit occurred on, which makes it easier to grep through logs that havemany tracing statements enabled.

Often, you may find that additional context would be beneficial.One way to add context is to include a marker in all of the output.This lets you add a semantic name to any spy:

spyscope.repl=> #spy/d ^{:marker"triple-add"} (+123)spyscope.repl$eval3935.invoke(NO_SOURCE_FILE:1) triple-add (+123) =>66

In addition, you can request additional stack frames with themetadata key:fs, which gives you a richer context without youdoing anything:

aside: (:fs comes from first and last letters of "frames")

spyscope.repl=> (take20 (repeat #spy/d ^{:fs3} (+123)))----------------------------------------clojure.lang.Compiler.eval(Compiler.java:6477)clojure.lang.Compiler.eval(Compiler.java:6511)spyscope.repl$eval675.invoke(REPL:13) (+123) =>6(66666666666666666666)

As you can see, when multiple stack frames are printed, a row of dashesis printed before the trace to keep the start of the stack frame groupclearly denoted.

As you debug further, you may realize that the context of the creation ofcertain values is important; however, if you print out 10 or 20 lines ofstack trace, you'll end up with an unreadable mess. The metadata key:nsesallows you to apply a regex to the stacktrace frames to filter out noise:

spyscope.repl=> (take20 (repeat #spy/d ^{:fs3:nses#"core|spyscope"} (+123)))----------------------------------------clojure.core$apply.invoke(core.clj:601)clojure.core$eval.invoke(core.clj:2797)spyscope.repl$eval678.invoke(REPL:14) (+123) =>6(66666666666666666666)

If you leave your application unattended for a period of time, you maywish to have timestamps included in all the output lines. Spyscope can usea default time format, or a user-provided one:

;; Default formatter is yyyy-mm-ddThh:mm:ssspyscope.repl=> #spy/d ^{:timetrue} (+123)spyscope.repl$eval4028.invoke(NO_SOURCE_FILE:1)2013-04-11T03:20:46 (+123) =>66

;; Custom formatters use clj-timespyscope.repl=> #spy/d ^{:time"hh:mm:ss"} (+123)spyscope.repl$eval4061.invoke(NO_SOURCE_FILE:1)03:21:40 (+123) =>66

The last feature of#spy/d is that it can suppress printing the codethat generated the value, which can be used to de-clutter the outputif you have particularly large forms. This is controlled by settingthe metadata key:form tofalse:

spyscope.repl=> {:a #spy/d ^{:formfalse} (+123):b #spy/d ^{:formfalse} (-1610)}spyscope.repl$eval685.invoke(REPL:16) =>6spyscope.repl$eval685.invoke(REPL:16) =>6{:a6,:b6}

Under the hood,#spy/d actually does all of its printing on another thread--the tracing store thread! This provides 2 benefits: if you are printingfrom multiple threads, your output will not be interleaved amongst threads. Theother benefit is that every trace statement is logged, so that you can usethe#spy/t api to refine your search after you start tracing with#spy/d.

Finally, let's look at#spy/t. Tracing is very similar to detailedprinting, but it enables us to get meaningful results when using#spy/don a program that has multiple interacting threads without affectingmost interactive development workflows!

#spy/t accepts all of the metadata arguments that#spy/d does (i.e.:fs,:nses, and:form).

Instead of immediately printing out results, it stores them in anagent asynchronously. Each time a trace is logged, it is placed intothe current generation. One can use a function to increment the generationcounter, and previous generations are stored, so that one can compareseveral recent generations to understand what effects changes may have had.

There are several functions you can use to interact with the trace store:

• trace-query is the workhorse function. With no arguments, it prints everytrace from the current generation. With a numeric argumentgenerations,it prints every trace from the pastgenerations generations. With aregex argumentre, it prints every trace from the current generation whoseroot stack frame matches the regex. Also accepts 2 arguments to specify thefiltering regex and how many generations to include.

• trace-next moves onto the next generation. One usually calls this betweentrials or experiments.

• trace-clear deletes all trace data collected so far. Since all tracedata is saved, that can become quite a lot of data, so this can be usedto clean up very long running sessions.

;;Let's run some code on futures, but see the chronological resultuser=> (future (Thread/sleep1000) #spy/t ^{:formfalse} (+12))       (future #spy/t (+34))#<Future@1013d7df::pending>;;We'll need to use the repl functionsuser=> (use 'spyscope.repl)nil;;trace-query shows all the traces by default, separated by dashed linesuser=> (trace-query)user$eval35677$fn__35689.invoke(NO_SOURCE_FILE:1) (+34) =>7----------------------------------------user$eval35677$fn__35678.invoke(NO_SOURCE_FILE:1) =>3nil;;We'll define and invoke a function with a #spy/tuser=> (defnmy-best-fn [] #spy/t ^{:formfalse} (*56))       (my-best-fn)30;Here's the return value--note that the trace isn't printed;;Let's see all traces so faruser=> (trace-query)user$eval35677$fn__35689.invoke(NO_SOURCE_FILE:1) (+34) =>7----------------------------------------user$eval35677$fn__35678.invoke(NO_SOURCE_FILE:1) =>3----------------------------------------user$eval35822$my_best_fn__35823.invoke(NO_SOURCE_FILE:1) =>30;Here's our new tracenil;;We can use a filter regex to only see matching stack frames;;Usually, you can filter by the name of the innermost function;;You can increase the :fs metadata parameter to have more context to filter byuser=> (trace-query#"best")user$eval35822$my_best_fn__35823.invoke(NO_SOURCE_FILE:1) =>30nil;;Move onto a new generationuser=> (trace-next)nil;;No traces in this generationuser=> (trace-query)nil;;Increase the number of generations in the query to review older tracesuser=> (trace-query2)user$eval35677$fn__35689.invoke(NO_SOURCE_FILE:1) (+34) =>7----------------------------------------user$eval35677$fn__35678.invoke(NO_SOURCE_FILE:1) =>3----------------------------------------user$eval35822$my_best_fn__35823.invoke(NO_SOURCE_FILE:1) =>30nil;;Add a new trace to the current generationuser=> (my-best-fn)30;;We can see that there's only one trace in this generation--the one we just madeuser=> (trace-query)user$eval35822$my_best_fn__35823.invoke(NO_SOURCE_FILE:1) =>30nil;;We can combine the generation and regex filter to search and filter many generations;;Here we see the invocations of my-best-fn from the current and previous generationuser=> (trace-query#"best"2)user$eval35822$my_best_fn__35823.invoke(NO_SOURCE_FILE:1) =>30----------------------------------------user$eval35822$my_best_fn__35823.invoke(NO_SOURCE_FILE:1) =>30niluser=>

David Greenberg (@dgrnbrg) and Herwig Hochleitner (@bendlas)

Copyright © 2012 David Greenberg

Distributed under the Eclipse Public License, the same as Clojure.