Debug Messages

To follow along with this section, start with tag v2.0.6.

The dataflow system built into pedestal-app does a lot of work for you. As you create an application you may want to gain some visibility into what is going on within the dataflow. One thing that you might want to know is, how long does it take to process a single message?

You can get debug information from the dataflow as messages by adding :debug true to the dataflow definition.

:debug true

You can then provide a transform function to process these messages. Debug messages will have a type of :debug and the topic will start with :pedestal. For this application, you can use the existing swap-transform function.

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

To report these changes, add a new emitter which will report all of the pedestal-app debug changes without adding a prefix. This will cause all of this data to appear under the top-level :pedestal key.

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

After making these changes, if you refresh the browser you 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. It would be more useful to know both the average and maximum dataflow times.

There is already a function for calculating the maximum from a set of inputs. To apply this to the dataflow time you only need to update the :derive section of the dataflow definition.

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

It would also be helpful to have 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. If you calculate the cumulative average of a value at [:pedestal :debug :dataflow-time] then the result value will be located at [:pedestal :debug :dataflow-time-avg].

Configure this derive function.

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

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

If you refresh the Data UI, you will notice that all of the data under [:pedestal :debug] is being displayed. To see only the interesting values, explicitly list the paths to those values as inputs to the emitter.

[#{[: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 you 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 the 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 you will see how Post Processing can be used to apply transformations to data without complicating dataflow code.

The tag for this section is v2.0.7.

Home | Post Processing