How to extend the time scale of django connection.queries output?

Question

Currently I have this output:

from django.db import connection
print connection.queries

Output: [{'time': '0.000', ...

I wanted to output to be like: [{'time': '0.000000', ...

Is it possible. If yes how? If not why not? Most of my SQL Queries get executed in 0.000 time frame. Basically I want to implement this feature so that when I set up my DEBUG True in settings.py and make necessary changes I want to be able to see the SQL Execution times of small time fraction also in my log.

If a query takes `0.0001` second or `0.00001` seconds, it won't make any noticeable difference to the load time of your page, unless you have thousands of queries. If you have thousands of queries, then concentrate on reducing that, rather than worrying whether they take `0.0001` or `0.00001` seconds. — Alasdair, Nov 17 '16 at 10:06
I have 10s of thousands of queries. I wanted to optimize on places where I can. Thanks. — Bishwas Mishra, Nov 17 '16 at 11:25
The latency of a production database may be significantly higher than the latency on your local development machine -- especially if you have to scale up your website and put the database on a different machine. Even an increase of, say, 1ms in latency means that 10.000 queries will need an additional 10 seconds to complete. At that point, all your hard work to optimize your queries is pointless, and you _need_ to scale down the number of queries. — knbk, Nov 17 '16 at 12:55
Okay. These two suggestions give me new insights. Thanks @Alasdair and@knbk — Bishwas Mishra, Mar 05 '17 at 10:53

score 4 · Accepted Answer · answered Nov 17 '16 at 10:08

This is filled by the CursorDebugWrapper class located in django.db.backends.utils. This is also where the query time is cut short.

'time': "%.3f" % duration,

If you want more digits you will need to create your own CursorDebugWrapper and monkeypatch the BaseDatabaseWrapper where it's initiated or create your own database backend.

def make_debug_cursor(self, cursor):
    """
    Creates a cursor that logs all queries in self.queries_log.
    """
    return utils.CursorDebugWrapper(cursor, self)

score -1 · Answer 2 · answered Jun 15 '20 at 04:37

If you're using a setup like this you can use a formatter e.g.

LOGGING = {
    'version': 1,
    'loggers': {
        'django.db.backends': {
            'level': 'DEBUG',
            'handlers': ['console']
        }
    },
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'my_time'
        }
    },
    'formatters': {
        'my_time': {
            'format': 'Time: {duration:.8f} s\nSQL: {sql}\nArgs: {params}',
            'style': '{'
        }
    }
}

where you can increase .8f to get more precision. The above would produce something like the following

Time: 0.00350088 s
SQL: SELECT ...
Args: (...)

How to extend the time scale of django connection.queries output?

2 Answers2