Sayid (siy EED) is a tool for debugging and profiling clojure code.

Sayid works by intercepting and recording the inputs and outputs of functions. It can even record function calls that occur inside of functions. The user can select which functions to trace. Functions can be selected individually or by namespace. The recorded data can be displayed, queried and profiled.

Sayid currently has three components:

  • core and its supporting namespaces
  • nREPL middleware
  • an emacs-cider nREPL client
    • although a 3rd-party vim plugin also exists. See this and this.

The core namespace is designed to be used directly via a repl and does not require emacs or cider. BUT the emacs-cider integration offers a far better experience, so it is the current focus of this page and my development efforts.

github repo

contents

Contents

Installation & Requirements

Basic usage requires Clojure 1.7. Add this to the dependencies in your project.clj or lein profiles.clj:

[com.billpiel/sayid "0.0.15"]

For the full emacs+cider experience, you'll want to include Sayid as a plug-in, as well as nREPL. I think the minimum required cider-nREPL version is "0.10.0". Here's an example of a bare-bones profiles.clj that works for me:

 {:user {:plugins [[cider/cider-nrepl "0.14.0"]
                   [com.billpiel/sayid "0.0.15"]]
         :dependencies [[org.clojure/tools.nrepl "0.2.12"]]}}

The emacs+cider setup also requires that the emacs package is installed. It's available on MELPA and MELPA Stable. Put this code in init.el, or somewhere, to load keybindings for clojure-mode buffers.

 (eval-after-load 'clojure-mode
   '(sayid-setup-package))

Conj 2016 Presentation

I presented Sayid at the Clojure Conj conference in Austin in 2016.

Demo #1 - Video

A demo video I recorded after the very first alpha release. You can find the contrived example project here.

Demo #1 - Walkthrough

This is a written walkthrough of the same steps illustrated in the demo video above, but with Sayid v0.0.8. You can find the contrived example project here.

Below is the code to the test namespace. You can see that we have a vending machine that dispenses tacos for 85 cents. We execute the test1 function, which inserts 41 cents worth of change and presses the taco button.

 (ns contrived-example.core-test
   (:require [clojure.test :refer :all]
             [contrived-example.core :as ce]))
 
 
 (def test-vending-machine {:inventory {:a1 {:name :taco
                                             :price 0.85
                                             :qty 10}}
                            :coins-inserted []
                            :coins-returned []
                            :dispensed nil
                            :err-msg nil})
 
 (defn test1 []
   (-> test-vending-machine
       (ce/insert-coin :quarter) ;; 25
       (ce/insert-coin :dime)    ;; 35
       (ce/insert-coin :nickel)  ;; 40
       (ce/insert-coin :penny)   ;; 41 cents
       (ce/press-button :a1)))   ;; taco costs 85 cents
 
 (test1)

Let's press some keys to get Sayid going.

eval the namespace - C-c C-k (probably)

trace the project namespaces - C-c s t p contrived-example.*

This should pop up. It shows how many functions have been traced in which namespaces. Execute test1!

Traced namespaces:
  5 / 5  contrived-example.core
  1 / 1  contrived-example.core-test
  8 / 8  contrived-example.inner-workings


Traced functions:

You can't tell yet, but something magical happened. Press C-c s w to get an overview of what has been captured in the Sayid workspace. This monster should appear:

v contrived-example.core-test/test1  :13446
|v contrived-example.core/insert-coin  :13447
|^ 
|v contrived-example.core/insert-coin  :13448
|^ 
|v contrived-example.core/insert-coin  :13449
|^ 
|v contrived-example.core/insert-coin  :13450
|^ 
|v contrived-example.core/press-button  :13451
||v contrived-example.inner-workings/valid-selection  :13452
|||v contrived-example.inner-workings/get-selection  :13453
|||^ 
|||v contrived-example.inner-workings/calc-coin-value  :13454
|||^ 
||| contrived-example.inner-workings/valid-selection  :13452
||^ 
||v contrived-example.inner-workings/process-transaction  :13455
|||v contrived-example.inner-workings/get-selection  :13456
|||^ 
|||v contrived-example.inner-workings/calc-change-to-return  :13457
||||v contrived-example.inner-workings/calc-coin-value  :13458
||||^ 
||||v contrived-example.inner-workings/round-to-pennies  :13459
||||^ 
||||v contrived-example.inner-workings/calc-change-to-return*  :13460
|||||v contrived-example.inner-workings/calc-coin-value  :13461
|||||^ 
|||||v contrived-example.inner-workings/calc-change-to-return*  :13462
||||||v contrived-example.inner-workings/calc-coin-value  :13463
||||||^ 
||||||v contrived-example.inner-workings/calc-change-to-return*  :13464
|||||||v contrived-example.inner-workings/calc-coin-value  :13465
|||||||^ 
|||||||v contrived-example.inner-workings/calc-change-to-return*  :13466
||||||||v contrived-example.inner-workings/calc-coin-value  :13467
||||||||^ 
|||||||| contrived-example.inner-workings/calc-change-to-return*  :13466
|||||||^ 
|||||||v contrived-example.inner-workings/calc-change-to-return*  :13468
||||||||v contrived-example.inner-workings/calc-coin-value  :13469
||||||||^ 
|||||||| contrived-example.inner-workings/calc-change-to-return*  :13468
|||||||^ 
|||||||v contrived-example.inner-workings/calc-change-to-return*  :13470
||||||||v contrived-example.inner-workings/calc-coin-value  :13471
||||||||^ 
|||||||| contrived-example.inner-workings/calc-change-to-return*  :13470
|||||||^ 
||||||| contrived-example.inner-workings/calc-change-to-return*  :13464
||||||^ 
|||||| contrived-example.inner-workings/calc-change-to-return*  :13462
|||||^ 
||||| contrived-example.inner-workings/calc-change-to-return*  :13460
||||^ 
|||| contrived-example.inner-workings/calc-change-to-return  :13457
|||^ 
||| contrived-example.inner-workings/process-transaction  :13455
||^ 
|| contrived-example.core/press-button  :13451
|^ 
| contrived-example.core-test/test1  :13446
^ 

What's the meaning of this? These are all the function calls that were made in the traced namespaced when we execute test1.

Let's explore. Get your cursor to the first line of the output and press i.

 v contrived-example.core-test/test1  :13446
 | returned =>  {:inventory {:a1 {:name :taco :price 0.85 :qty 9}} 
 |               :coins-inserted []                                
 |               :coins-returned [:quarter :quarter :nickel]       
 |               :dispensed {:name :taco :price 0.85 :qty 10}      
 |               :err-msg nil}                                     
 ^ 
 

This shows us the details of that instance of test1 being called. We can see that a hash map was returned. Despite us inserting only 41 cents for an 85 cent taco, we see that a taco was dispensed, plus change! That's a BUG.

Hit backspace. We're back at the overview. Scan the list of functions that are called. Let's assume some programmer's intuition and decide that valid-selection is the first place of interest. Get your cursor to that line and press these keys to view the instance and all of its descendants. I d ENTER

 ||v contrived-example.inner-workings/valid-selection  :13452
 ||| machine => {:inventory {:a1 {:name :taco :price 0.85 :qty 10}} 
 |||             :coins-inserted [:quarter :dime :nickel :penny]    
 |||             :coins-returned []                                 
 |||             :dispensed nil                                     
 |||             :err-msg nil}                                      
 ||| button => :a1 
 ||| returns =>  true 
 |||v contrived-example.inner-workings/get-selection  :13453
 |||| machine => {:inventory {:a1 {:name :taco :price 0.85 :qty 10}} 
 ||||             :coins-inserted [:quarter :dime :nickel :penny]    
 ||||             :coins-returned []                                 
 ||||             :dispensed nil                                     
 ||||             :err-msg nil}                                      
 |||| button => :a1 
 |||| returned =>  {:name :taco :price 0.85 :qty 10} 
 |||^ 
 |||v contrived-example.inner-workings/calc-coin-value  :13454
 |||| coins => [:quarter :dime :nickel :penny] 
 |||| returned =>  1.4 
 |||^ 
 ||| contrived-example.inner-workings/valid-selection  :13452
 ||| machine => {:inventory {:a1 {:name :taco :price 0.85 :qty 10}} 
 |||             :coins-inserted [:quarter :dime :nickel :penny]    
 |||             :coins-returned []                                 
 |||             :dispensed nil                                     
 |||             :err-msg nil}                                      
 ||| button => :a1 
 ||| returned =>  true 
 ||^ 
 

We can see that valid-selection makes calls to get-selection and calc-coin-value. Looking at the return values, we might notice a problem: calc-coin-value receives [:quarter :dime :nickel :penny] but returns $1.40 as the value. Let's dig deeper. Press n a couple times to get the cursor to the call to calc-coin-value. Now press N and hold onto your hat.

 ||||v (->> coins (keep coin-values) (apply +)) => (apply + (keep coin-values coins))  contrived-example.inner-workings/calc-coin-value  :13491
 ||||| returns =>  1.4 
 |||||v (apply + (keep coin-values coins))  contrived-example.inner-workings/calc-coin-value  :13492
 |||||| #function[clojure.core/+] 
 |||||| (0.25 0.1 0.05 1) 
 |||||| returns =>  1.4 
 ||||||v (keep coin-values coins)  contrived-example.inner-workings/calc-coin-value  :13493
 ||||||| {:quarter 0.25 :dime 0.1 :nickel 0.05 :penny 1} 
 ||||||| [:quarter :dime :nickel :penny] 
 ||||||| returned =>  (0.25 0.1 0.05 1) 
 ||||||^ 
 |||||| (apply + (keep coin-values coins))  contrived-example.inner-workings/calc-coin-value  :13492
 |||||| #function[clojure.core/+] 
 |||||| (0.25 0.1 0.05 1) 
 |||||| returned =>  1.4 
 |||||^ 
 ||||| (->> coins (keep coin-values) (apply +)) => (apply + (keep coin-values coins))  contrived-example.inner-workings/calc-coin-value  :13491
 ||||| returned =>  1.4 
 ||||^
...truncated...

(jump to the top of the buffer)
What did we do? We applied an inner trace to the function calc-coin-value and then replayed the call to test1 that we had captured originally.

An INNER trace? YES! We can see the inputs and output values of each expression in the function. Look at it. Where do things go wrong? It's when we pass a hash map to keep that defines a penny as being worth a dollar. Bug located! Press n a couple times to get your cursor to that call. Press ENTER to jump to that line of code.

 (ns contrived-example.inner-workings)
 
 (def coin-values
   {:quarter 0.25
    :dime 0.10
    :nickel 0.05
    :penny 1})
 
 (defn- calc-coin-value
   [coins]
   (->> coins
        (keep coin-values)
        (apply +)))

...truncated...

We now find ourselves at the troublesome call to keep causing our bug. The hash map, coin-values, is just above. Change the value of a penny from 1 to 0.01. Let's eval our corrected code the Sayid way -- press C-c s !. This will remove the traces, eval the buffer, then re-apply the traces. It also clears the workspace log. This is all helpful. Navigate back to core-test and run test1 again. Repeating steps above, you can verify the output is now correct: no taco.

 v contrived-example.core-test/test1  :13579
 | returned =>  {:inventory {:a1 {:name :taco :price 0.85 :qty 10}} 
 |               :coins-inserted [:quarter :dime :nickel :penny]    
 |               :coins-returned []                                 
 |               :dispensed nil                                     
 |               :err-msg true}                                     
 ^ 
 

Great work!

Documentation

Documentation is a little light at the moment. There are lists of keybindings. Helpfully, they are easily accessible from within emacs. Below are the contents of the various help buffers, as well as instructions on how to pop them up in time of need.

Generated docs are also available for the core namespace here.

In a clojure-mode buffer, press C-c s h to pop up the help buffer.

C-c s ! -- Disble traces, eval current buffer, enable traces, clear the workspace log
C-c s e -- Enables traces, evals the expression at point, disables traces, displays results with terse view
C-c s f -- Queries the active workspace for entries that most closely match the context of the cursor position
C-c s n -- Applies an inner trace to the function at point, replays workspace, displays results
C-c s r -- Replays workspace, queries results by context of cursor
C-c s w -- Shows workspace, using the current view
C-c s t y -- Prompts for a dir, recursively traces all ns's in that dir and subdirs
C-c s t p -- Prompts for a pattern (* = wildcare), and applies a trace to all *loaded* ns's whose name matches the patten
C-c s t b -- Trace the ns in the current buffer
C-c s t e -- Enable the *existing* (if any) trace of the function at point
C-c s t E -- Enable all traces
C-c s t d -- Disable the *existing* (if any) trace of the function at point
C-c s t D -- Disable all traces
C-c s t n -- Apply an inner trace to the symbol at point
C-c s t o -- Apply an outer trace to the symbol at point
C-c s t r -- Remove existing trace from the symbol at point
C-c s t K -- Remove all traces
C-c s c -- Clear the workspace trace log
C-c s x -- Blow away workspace -- traces and logs
C-c s s -- Popup buffer showing what it currently traced
C-c s S -- Popup buffer showing what it currently traced in buffer's ns
C-c s V s -- Set the view
C-c s h -- show this help
                      

In the *sayid* buffer, press h to pop up the help buffer.

ENTER -- pop to function
d -- def value to $s/*
f -- query for calls to function
F -- query for calls to function with modifier
i -- show only this instance
I -- query for this instance with modifier
w -- show full workspace trace
n -- jump to next call node
N -- apply inner trace and reply workspace
p -- jump to prev call node
P -- pretty print value
C -- clear workspace trace log
v -- toggle view
V -- set view (see register-view)
l, backspace -- previous buffer state
L, S-backspace -- forward buffer state
g -- generate instance expression and put in kill ring
h -- help                        
                      

In the *sayid-traced* buffer, press h to pop up the help buffer.

enter -- Drill into ns at point
e -- Enable trace
d -- Disable trace
E -- Enable ALL traces
D -- Disable ALL traces
i -- Apply inner trace to func at point
o -- Apply outer trace to func at point
r -- Remove trace from fun at point
l, backspace -- go back to trace overview (if in ns view)
                      

In the *sayid-pprint* buffer, press h to pop up the help buffer.

ENTER -- show path in mini-buffer
i -- jump into child node
o -- jump out to parent node
n -- jump to next sibling node
p -- jump to previous sibling node