what else is the Rails controller doing?

Question

I have a Rails 4.2 app which is printing shipping labels. The New Relic instrumentation shows that it spends 35% of the time in the controller (not including the operations of the controller method), and I don't understand why. The app flow is simple:

1. Authenticate user
2. Build AR object
3. Validate address (external microservice call)
4. Calculate price
5. Generate tracking number in Redis
6. Persist AR to PG
7. Generate tracking number
8. Generate response

Step 1 is done with Devise which queries PG. Step 2 through 8 are wrapped in LabelsController#generate (more exactly a service class which the controller calls).

The New Relic tracing shows all these steps and how long they take. It shows that LabelsController#generate takes 229ms - but that's without CalculatePrice (138ms), DrawLabel (118ms), etc. even though #generate calls CalculatePrice, DrawLabel, etc. It's just New Relic's way to breakdown custom tracing. If I wouldn't have added specific custom tracing to all these, then it would correctly aggregate CalculatePrice, DrawLabel, ValidateAddress, etc. under #generate (which would be close to 800ms). So... if I already instrumented all the steps in #generate, what else does the controller do that takes so long (other than executing the body of the action method)? Is this where the Rails locking takes place? I thought that's in one of the middlewares.

This is the tracking of only 1 request on one server instance.

Answer 1

After I added more instrumentation, it turns out the other 33% of the call in the controller: JSON schema verification and Devise authentication.