Debug Messages

Debug Messages

The dataflow system built into Pedestal does a lot of work for us. We may want to gain some visibility into what is going on within the dataflow. One thing that we might want to know is, how long does it take for our dataflow to run?

We can get debug information from the dataflow as messages which are sent to the dataflow by adding :debug true to the dataflow definition.

:debug true

We can then respond to :debug type messages using our swap-transform function.

[:debug [:pedestal :**] swap-transform]

To report these changes, we add a new emitter which will report all of the Pedestal debug changes without adding a prefix.

[#{[:pedestal :debug :*]} (app/default-emitter [])]

After making these changes, if we refresh the browser we should see the :dataflow-time being reported (at the time of this writing, that is the only debug information that is reported). This is the amount of time in milliseconds that it takes to run a single dataflow transaction.

Derive interesting information from the debug data

This value is interesting but not very informative. Let's add a couple more derive functions to provide more information.

It would we nice to know the maximum dataflow run time. We already have a function for calculating the maximum from a set of inputs. To apply this to the dataflow time we only need to update the :derive section of the dataflow.

[#{[:pedestal :debug :dataflow-time]} [:pedestal :debug :dataflow-time-max] maximum :vals]

Because the maximum function is not coupled to inputs and outputs we can simply reuse it here.

We would also like to store a cumulative average of all dataflow run times without having to store all the times.

(defn cumulative-average [debug key x]
  (let [k (last key)
        i (inc (or (::avg-count debug) 0))
        avg (or (::avg-raw debug) 0)
        new-avg (+ avg (/ (- x avg) i))]
    (assoc debug
      ::avg-count i
      ::avg-raw new-avg
      (keyword (str (name k) "-avg")) (int new-avg))))

Because this function needs to know the total number of times and the old average, it updates the map located at [:pedestal :debug]. It stores these values in the map as well as the average as an integer value under a key based on the last part of the input path. So if we calculate the cumulative average of a value at [:pedestal :debug :dataflow-time] then the result value that we want will be located at [:pedestal :debug :dataflow-time-avg].

Next, we configure this in the dataflow definition.

[#{[:pedestal :debug :dataflow-time]} [:pedestal :debug] cumulative-average :map-seq]

Here :map-seq is used so that we can easily grab the key and value as two separate arguments.

If we refresh and view the screen, we will see that all of the data under [:pedestal :debug] is being displayed. We would like to only see the three values we are interested in.

[#{[:pedestal :debug :dataflow-time]
   [:pedestal :debug :dataflow-time-max]
   [:pedestal :debug :dataflow-time-avg]} (app/default-emitter [])]

This should now work correctly.

With the changes that we made in this and the previous section, the dataflow description now looks like this:

(def example-app
  {:version 2
   :debug true
   :transform [[:inc   [:my-counter]   inc-transform]
               [:swap  [:**]           swap-transform]
               [:debug [:pedestal :**] swap-transform]]
   :derive #{[{[:my-counter] :me [:other-counters] :others} [:counters] merge-counters :map]
             [#{[:counters :*]} [:total-count] total-count :vals]
             [#{[:counters :*]} [:max-count] maximum :vals]
             [{[:counters :*] :nums [:total-count] :total} [:average-count] average-count :map]
             [#{[:pedestal :debug :dataflow-time]} [:pedestal :debug :dataflow-time-max]
              maximum :vals]
             [#{[:pedestal :debug :dataflow-time]} [:pedestal :debug] cumulative-average :map-seq]}
   :effect #{[#{[:my-counter]} publish-counter :single-val]}
   :emit [{:init init-main}
          [#{[:my-counter]
             [:other-counters :*]
             [:total-count]
             [:max-count]
             [:average-count]} (app/default-emitter [:main])]
          [#{[:pedestal :debug :dataflow-time]
             [:pedestal :debug :dataflow-time-max]
             [:pedestal :debug :dataflow-time-avg]} (app/default-emitter [])]]})

Next steps

The behavior of our application is mostly complete. There is only one thing left to do. You may have noticed that the average count value is not very well behaved. It would be nice if that value was rounded to 2 decimal places. In the next section we see how Post Processing can be used to apply transformations to data without complicating dataflow code.

The tag for this step is v2.0.7.

Home | Post Processing