Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Query timing information is incorrect/misleading #1491

Open
cs278 opened this issue Feb 20, 2025 · 0 comments
Open

Query timing information is incorrect/misleading #1491

cs278 opened this issue Feb 20, 2025 · 0 comments

Comments

@cs278
Copy link

cs278 commented Feb 20, 2025

Bug Report

Q A
BC Break no
Version 3.8.2

Summary

The time taken for each query shown via --query-time is incorrect.

Current behavior

Currently the migrator measures the cumulative time taken for all queries but presents it as the time taken for each individual query.

How to reproduce

Write a simple migration like:

        $this->addSql('SELECT 1');
        $this->addSql('SELECT SLEEP(1)');
        $this->addSql('SELECT 1');
        $this->addSql('SELECT SLEEP(1)');
        $this->addSql('SELECT 1');
        $this->addSql('SELECT SLEEP(1)');
        $this->addSql('SELECT 1');

Execute with bin/console doctrine:migrations:migrate --query-time.

You'll see all but the first SELECT 1 queries are shown taking seconds to complete rather than the actual sub-millisecond runtime.

notice] Migrating up to Migrations\Version20250203131759
[notice] SELECT 1 
[notice] Query took 0.3ms
[notice] SELECT SLEEP(1) 
[notice] Query took 1000.8ms
[notice] SELECT 1 
[notice] Query took 1001.4ms
[notice] SELECT SLEEP(1) 
[notice] Query took 2002ms
[notice] SELECT 1 
[notice] Query took 2003ms
[notice] SELECT SLEEP(1) 
[notice] Query took 3004.2ms
[notice] SELECT 1 
[notice] Query took 3005.2ms
[notice] finished in 3022.9ms, used 26M memory, 1 migrations executed, 7 sql queries

Expected behavior

Something like:

notice] Migrating up to Migrations\Version20250203131759
[notice] SELECT 1 
[notice] Query took 0.3ms
[notice] SELECT SLEEP(1) 
[notice] Query took 1000.8ms
[notice] SELECT 1 
[notice] Query took 0.4ms
[notice] SELECT SLEEP(1) 
[notice] Query took 1002ms
[notice] SELECT 1 
[notice] Query took 0.5ms
[notice] SELECT SLEEP(1) 
[notice] Query took 1004.2ms
[notice] SELECT 1 
[notice] Query took 0.2ms
[notice] finished in 3022.9ms, used 26M memory, 1 migrations executed, 7 sql queries

Alternatively if this behaviour is desired Query took should be adapted to something like Queries have taken

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant