Issue: Fix count_queries to prevent couting pool events as queries.
Author: mkmoisen
State: closed
Created: 2022-02-21 03:58:43

When using the `count_queries()` function from the `playhouse.test_utils`, it does not give the expected count when you use a Pool. It includes things like opening a connection or returning the connection to the pool as a query.

The solution is to simply include log records from "peewee" not from "peewee.pool". I've tested this PR only on my local postgresql. 

Here is a demonstration of the bug:

```
from peewee import SQL
from playhouse.pool import PooledPostgresqlExtDatabase
from playhouse.test_utils import count_queries

db = PooledPostgresqlExtDatabase(
    'test', user='test', password='test', max_connections=1, autoconnect=False,
)

with count_queries() as counter:
    with db:
        db.execute(SQL('select 1'))

assert counter.count == 4

for query in counter.get_queries():
    print(query)


```

Here are the 4 queries recorded for me, instead of the expected 1.

```
<LogRecord: peewee.pool, 10, C:\test\lib\site-packages\playhouse\pool.py, 130, "No connection available in pool.">
<LogRecord: peewee.pool, 10, C:\test\lib\site-packages\playhouse\pool.py, 159, "Created new connection %s.">
<LogRecord: peewee, 10, C:\test\lib\site-packages\peewee.py, 3148, "('select 1', [])">
<LogRecord: peewee.pool, 10, C:\test\lib\site-packages\playhouse\pool.py, 186, "Returning %s to pool.">
```

The solution here is very simple, just make sure to only include logs emitted by "peewee" and nothing else (such as "peewee.pool").


Thanks, merged an equivalent patch.

Thanks. Is there any way to get the query execution time?

One of the nice things about django is that `connection.queries` stores the execution time of the query, so for example you can log all queries that take longer than 2 seconds:

    from django.db import connection
    for query in connection.queries:
       if query.time > 2:  # I cannot remember if it is query.time or maybe query[1]
            log_expensive_query(query)

(Actually this is only true in Django when debug mode is true which you shouldn't do in production. So in prod you have to write some custom middleware, I haven't tried that.)

You should really be using your databases built-in slow query logger for that.

While that is true, I do find the django connection.queries execution time useful while in development. 

I have my nonprod middleware dump connection.queries and I will visually check the time of each query to make sure I didn't forget an index for example. 

The alternative is to switch over to a psql shell and select from pg_stat_statements, and typing out the where clause to return only the relevant SQL. It's not too convenient compared to just reading the output of the django connection.queries.

---

Would you be open to adding timing execution to peewee? If you are, I believe the following change to `execute_sql` is backwards compatible. The logger emits a tuple of length 3 instead of length 2.



```
    def execute_sql(self, sql, params=None, commit=SENTINEL):
        if commit is SENTINEL:
            if self.in_transaction():
                commit = False
            elif self.commit_select:
                commit = True
            else:
                commit = not sql[:6].lower().startswith('select')

        with __exception_wrapper__:
            cursor = self.cursor(commit)
            start_time = datetime.datetime.now()
            try:
                cursor.execute(sql, params or ())
            except Exception:
                if self.autorollback and not self.in_transaction():
                    self.rollback()
                raise
            else:
                if commit and not self.in_transaction():
                    self.commit()
            finally:
                end_time = datetime.datetime.now()

        logger.debug((sql, params, (end_time - start_time).total_seconds()))

        return cursor
```

If you are insistent on wanting this in your Python code, then I suggest subclassing Database or implementing a mixin class and wrapping `execute_sql()` with whatever timing logic you want.