0

I have been using compojure-api to build a server and I have an endpoint that returns json to the client. Now the problem: it seems to me that it is taking too much time to build the response to send back to the client.

Here is my log. It shows that the entire procedure seems to go pretty fast, but to get back to the client, takes around 8 minutes on 4 cpu thinkpad. On a second run, I saved the json to see the size and it was 12k. Is this a big json and it is justified to take this long for the server to respond? I feel like it is not and most likely I am doing something wrong.

21:21:20.978 [qtp1190836072-15] INFO  capacity.capacity - lets go!
21:21:20.996 [qtp1190836072-15] INFO  capacity.capacity - finished big parts
21:21:22.590 [qtp1190836072-15] INFO  capacity.capacity - finished everything
21:21:22.590 [qtp1190836072-15] INFO  api-stuff.handler - ready to go class clojure.lang.PersistentArrayMap

Unfortunatly, I can not show the repo, but here I try to show some configurations of my router:


(def formats
  (m/create
    (-> m/default-options
        (m/install muuntaja.format.msgpack/format)
        ;; return byte[] for NIO servers
        (assoc :return :bytes))))

(def app
  (-> (api
       {
        :formats formats 
        :coercion nil 
        :swagger
        {:ui "/"
         :spec "/swagger.json"
         :format {:formats []}
         :data {:info {:title "Hopeffully a good example"
                       :description "API that may describe what I need"}
                :tags [{:name "api", :description "some apis"}]
                :consumes ["application/json"]
                :produces ["application/json" "text/csv"]}}}

       (context "/health" []
         :tags ["health check"]
         health-check ;; a get method for health check
        )

       (route-middleware [[hard-auth]]
         (context "/download" []
           :tags ["validation"]
           downloads ;; routes defined
         ))

       (route-middleware [[basic-auth-mw]]
         (context "/" []
           :tags ["api"]
           routes ;; routes defined that has my slow return
        )))))

A few things that I tried to change:

  1. change the format of the response (json and msgpack)
  2. I tried to use the default value of :coercion (without the key) and nil,

But these changes did not seem to make difference.

Lucas Moreira
  • 77
  • 9
  • Eight minutes for 12kb JSON is very unlikely unless your laptop goes into a powersaving mode. If I had to guess: your actual handler returns a lazy sequence, which still has all the work to do. So you see in your logging, that your code is "fast" but you moved all the work into the place, that actually has to realize the data. Is the timing in your log the same, if you make your handler eager? – cfrick Aug 16 '22 at 05:04
  • You nailed it! I did have a lazy sequence in the json to be returned. when I put a `doall` in between those logs, I was able to find the 8 minutes "delay". I am working on a solution (in this case to avoid the lazy sequence) and later I will share my solution in this case. Thank you! – Lucas Moreira Aug 16 '22 at 12:51

2 Answers2

0

As a fast way to get a ballpark estimate on which segments of your code are consuming time, may I suggest using tupelo.profile. Here is an example build using my favorite template project:

(ns tst.demo.core
  (:use demo.core tupelo.core tupelo.test)
  (:require
    [tupelo.profile :as prof]))

(verify
  (newline)
  (let [exponent 6
        upper    (long (Math/pow 10 exponent))
        vals     (vec (range 1 (inc upper))) ; 1..N

        expected (prof/with-timer-print :closed-form
                   (* (/ upper 2) (inc upper)))]

    (prof/with-timer-print :apply
      (is= expected (apply + vals)))
    (prof/with-timer-print :reduce
      (is= expected (reduce + vals)))
    (prof/with-timer-print :atom
      (let [cum (atom 0)]
        (doseq [n vals]
          (swap! cum + n))
        (is= expected @cum))))
  (newline))

with typical results:


-----------------------------------
   Clojure 1.11.1    Java 17.0.2
-----------------------------------

Testing tst.demo.core

:with-timer-print :closed-form     0.000009
:with-timer-print :apply           0.007105
:with-timer-print :reduce          0.006783
:with-timer-print :atom            0.021440


Testing tst.demo.other

Ran 3 tests containing 6 assertions.
0 failures, 0 errors.

Passed all tests
Finished at 21:25:38.122 (run time: 0.056s)
Alan Thompson
  • 29,276
  • 6
  • 41
  • 48
0

As suspected, I was tricking myself with the logs.

As @cfrick pointed out, I had a lazy sequence which was not being evaluated before the preparation for the response body. Because of that, I was loading all the trouble of evaluating after the log.

Once I organized my performance tests, I realized that the code that generated lazy sequence was taking a long time (8 minutes) once I evaluated the whole thing with doall.

The solution was to improve the time on that algorithm. Not much I can say without being specific.

Registering here in case it helps someone out there

Lucas Moreira
  • 77
  • 9