Django log filter for slow SQL queries

Question

I am currently logging all SQL queries thanks to the following LOGGING settings:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse'
        }
    },
    'formatters': {
        'standard': {
            'format' : "[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s",
            'datefmt' : "%d/%b/%Y %H:%M:%S"
        },
    },
    'handlers': {
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        },
        'console': {
            # logging handler that outputs log messages to terminal
            'class': 'logging.StreamHandler',
            'level': 'DEBUG', # message level to be written to console
        },
        'logfile': {
            'level':'DEBUG',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': os.path.join(os.path.dirname(os.path.dirname(os.path.abspath(__file__))), "log", "logfile"),
            'maxBytes': 50000,
            'backupCount': 2,
            'formatter': 'standard', 
        },
    },
    'loggers': {
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': True,
        },
        'django.db': {
            'handlers': ['logfile'],
            'level': 'DEBUG',
            'propagate': False,            # django also has database level logging
        },
    }
}

What I actually get in my logfile is:

[14/Jun/2013 13:54:19] DEBUG [django.db.backends:51] (0.000) SELECT "django_content_type"."id", "django_content_type"."name", "django_content_type"."app_label", "django_content_type"."model" FROM "django_content_type" WHERE "django_content_type"."app_label" = sites  ORDER BY "django_content_type"."name" ASC; args=(u'sites',)

I'd like to filter only queries that takes above 300ms to complete.

How should I write the filters section of my logging configuration, and what would look like the class that do the filtering?

Answer 1

You can use a filter to attach the stack_info:

class SlowQueriesFilter(logging.Filter):
    """Filter slow queries and attach stack_info."""

    def filter(self, record):
        duration = record.duration
        if duration > 0.1:
            # Same as in _log for when stack_info=True is used.
            fn, lno, func, sinfo = logging.Logger.findCaller(None, True)
            record.stack_info = sinfo
            return True
        return False

Add it to your filters list and then use it with the logger:

LOGGING = {
    'filters': {
        'slow_queries': {
            '()': 'app.log_filters.SlowQueriesFilter',
        },
    },
    'loggers': {
        'django.db.backends': {
            'level': 'DEBUG',
            'filters': ['slow_queries'],
        }
    }

Might require Python 3 for the stack_info handling, but a custom formatter could also be used.

Answer 2

So far, I've tried to use a CallbackFilter but I would prefer having a logging class.

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'queries_above_300ms': {
            '()': 'django.utils.log.CallbackFilter',
            'callback': lambda record: record.duration > 0.3 # output slow queries only
        },
    },
    'formatters': {
        'standard': {
            'format' : "[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s",
            'datefmt' : "%d/%b/%Y %H:%M:%S"
        },
    },
    'handlers': {
        'logfile': {
            'level':'DEBUG',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': os.path.join(os.path.dirname(os.path.dirname(os.path.abspath(__file__))), "log", "logfile"),
            'maxBytes': 50000,
            'backupCount': 2,
            'formatter': 'standard',
            'filters': ['queries_above_300ms'],
        },
    },
    'loggers': {
        'django.db': {
            'handlers': ['logfile'],
            'level': 'DEBUG',
            'propagate': False,
        },
    }
}