How do I diagnose django render speed problem?

I have been trying to figure out what is slowing down my requests, and all I can figure out is that there is some slowdown in the rendering of the response.

I ran some tests of the query, serializer, and JSON rendering like this:

client = Client.objects.get(user__username="pugdog")
start = parse("2021-09-01T00:00:00-04:00")
end = parse("2021-10-01T00:00:00-04:00")
db_test_start_time = time()
events = Event.objects.filter(client=client, start__gt=start, end__lt=end)
list(events)
db_test_end_time = time()

factory = APIRequestFactory()
request = factory.get('/')
serializer_context = {'request': Request(request), }
output = []
for event in events:
    serializer = EventReadSerializer(instance=event, context=serializer_context)
    output.append(serializer.data)
renderer = JSONRenderer()
json_output = renderer.render(output)
serializer_test_end_time = time()
print(f"query speed: {db_test_end_time - db_test_start_time}")
print(f"serializer speed: {serializer_test_end_time - db_test_end_time}")
print(f"Total time: {serializer_test_end_time - db_test_start_time}")

The output is:

query speed: 0.006450176239013672
serializer speed: 2.926229238510132
Total time: 2.9326794147491455

This is how long it takes to process the query and convert it to JSON, but when I try and pull this data using the API REST client “Insomnia”, it takes around 43.8 seconds, which means that I am having a massive slowdown somewhere. I am running Insomnia on the same machine I am developing on, so there should be no network issue.

This test is when I populate the database with 100 Event objects. I decided to do tests with different amounts of objects to see if the relationship between the amount of data and the response time was linear, which might be helpful in figuring out the problem, such as if there is some issue with my authorization/authentication, and it has nothing to do with the particular query. When I do 20 events, the time it takes to get the response in Insomnia is around 9 seconds, while the test above is about 0.6 seconds. This is almost a linear relationship to speed on both counts.

Most of my API is fairly responsive, but this particular part is extremely slow. What else can I test to figure out what is slowing things down?

EDIT Here is the EventReadSerializer

class EventReadSerializer(serializers.ModelSerializer):
    id = serializers.ReadOnlyField()
    resourceIds = ResourceIdsSerializer(source="resources", many=True)
    rrule = RRuleReadSerializer(many=True)
    customer = SimplifiedCustomerSerializer(many=False)

    class Meta:
        model = Event
        fields = [
            "id",
            "all_day",
            "title",
            "start",
            "end",
            "background_color",
            "border_color",
            "text_color",
            "duration",
            "resourceIds",
            "rrule",
            "customer",
        ]

Here is an example of a faked event after it is rendered:

{
    "id": 1,
    "all_day": false,
    "title": "Suddenly this mouth take.",
    "start": "2021-09-26T11:02:25Z",
    "end": "2021-09-26T12:02:25Z",
    "background_color": null,
    "border_color": null,
    "text_color": null,
    "duration": "01:00:00",
    "resourceIds": [
      2
    ],
    "rrule": [],
    "customer": {
      "id": 1,
      "user": {
        "first_name": "Craig",
        "last_name": "Johnson"
      },
      "custom_data": [],
      "notes": [],
      "first_name": "Craig",
      "last_name": "Johnson"
    }
  }

This is actually a pared down version of what was originally EventSerializer, which returned much more information. It is reduced to only the data needed for the calendar I am working with. This had no noticeable difference in final render speed. I also changed my CustomerSerializer to a SimplifiedCustomerSerializer in a similar manner, to reduce the amount of data returned.

Anyway, considering that when I run the script to test the speed, it runs the serializer in about 1/15th the time that it renders the page.

Another thing I have tried is to remove all middleware that I can to see how things change. While I did see a small improvement in speed, it dropped the time it took to render the page by about 2 seconds to 42.8 seconds, which is still seems completely unacceptable when compared to the 2.9 seconds it takes to run the query and serialize the data.

Answer

Your serializer does not only serializer the data of the instance, but from the related objects as well. This means that the serializer will make queries to the relatd models.

We can boost peroformance by using .select_related(…) [Django-doc] and .prefetch_related(…) [Django-doc]:

events = Event.objects.filter(
    client=client, start__gt=start, end__lt=end
).prefetch_related(
    'resources', 'rrule'
).select_related('customer', 'customer__user')

likely the Customer also makes queries to find the custom_data and the notes. If you share the corresponding Customer model and the SimplifiedCustomerSerializer serializer, we probably can reduce the number of queries for these items as well.