Unexpected output: Affected paths: relative - resubmit patch.
⚙ D392 INP-1794 - Show database query execution times during deployment
Page MenuHomeIn-Portal Phabricator

INP-1794 - Show database query execution times during deployment
ClosedPublic

Authored by alex on Dec 23 2020, 9:16 AM.

Details

Test Plan

Preparations

  1. replace contents of the /modules/custom/install/project_upgrades.sql file with this (replace 52x_ with your table prefix from /system/config.php):
# r1: Initial Project Task (#TASK_ID)
SELECT SLEEP(2);
SELECT SLEEP(7);

# r2: Another Task (#TASK_ID2)
SELECT SLEEP(65);
SELECT Version
FROM `52x_Modules`;

# r3: Yet Another Task (#TASK_ID3)
SELECT SLEEP(354);
SELECT Version
FROM `52x_Modules`;
  1. clear contents of /system/.restricted/project_upgrades.log file
  2. execute UPDATE 52x_Modules` SET AppliedDBRevisions = NULL; (replace 52x_` with your table prefix from /system/config.php) database query

Test 1 itself (takes 7-8 minutes to execute !!!)

  1. run the php tools/run_event.php adm:OnDeploy b674006f3edb1d9cd4d838c150b0567d script
  2. confirm, that contents of SQL-related part of deployment script output looks like this:
# r1: Initial Project Task (#TASK_ID)
SELECT SLEEP(2) ... OK (1) *Time*: 2s
SELECT SLEEP(7) ... OK (1) *Time*: 7s

# r2: Another Task (#TASK_ID2)
SELECT SLEEP(65) ... OK (1) *Time*: 1m 5s
SELECT Version FROM `52x_Modules` ... OK (7) *Time*: 0s

# r3: Yet Another Task (#TASK_ID3)
SELECT SLEEP(354) ... OK (1) *Time*: 5m 54s
SELECT Version FROM `52x_Modules` ... OK (7) *Time*: 0s

Total SQL Time: 7m 8s
  1. confirm, that from the above output:
  2. the *Time*: 2s, *Time*: 7s and *Time*: 0s text is shown in regular green color (as OK text before it)
  3. the *Time*: 1m 5s text is shown in cyan bold color
  4. the *Time*: 5m 54s and Total SQL Time: 7m 8s text is shown in red bold color
  5. the Total SQL Time: 7m 8s text represents total SQL run time across all executed SQL revisions
  6. confirm, that text added into /system/.restricted/project_upgrades.log looks like this (execution start/end date/times would be different, but durations must match):
[2020-12-28 16:39:08] ===  ===

# r1: Initial Project Task (#TASK_ID)
SELECT SLEEP(2); ... OK (1)
Duration: 2s (from 2020-12-28 16:39:08 to 2020-12-28 16:39:10)
SELECT SLEEP(7); ... OK (1)
Duration: 7s (from 2020-12-28 16:39:10 to 2020-12-28 16:39:17)

# r2: Another Task (#TASK_ID2)
SELECT SLEEP(65); ... OK (1)
Duration: 1m 5s (from 2020-12-28 16:39:17 to 2020-12-28 16:40:22)
SELECT Version
FROM `52x_Modules`; ... OK (7)
Duration: 0s (from 2020-12-28 16:40:22 to 2020-12-28 16:40:22)

# r3: Yet Another Task (#TASK_ID3)
SELECT SLEEP(354); ... OK (1)
Duration: 5m 54s (from 2020-12-28 16:40:22 to 2020-12-28 16:46:16)
SELECT Version
FROM `52x_Modules`; ... OK (7)
Duration: 0s (from 2020-12-28 16:46:16 to 2020-12-28 16:46:16)

Total Duration: 7m 8s

Test 2

  1. add up these lines to the /modules/custom/install/project_upgrades.sql file (replace 52x_ with your table prefix from /system/config.php):
# r4: Initial Project Task (#TASK_ID)

SELECT SLEEP(2);
ERROR;
  1. run the php tools/run_event.php adm:OnDeploy b674006f3edb1d9cd4d838c150b0567d script
  2. confirm, that the contents of the SQL-related part of deployment script output look like this:
# r4: Initial Project Task (#TASK_ID)
SELECT SLEEP(2) ... OK (1) *Time*: 2s
ERROR ... FAILED
SQL Error #1064: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'ERROR' at line 1
Please execute rest of SQLs in this Revision by hand and run deployment script again.

Total SQL Time: 2s
  1. confirm, that text added into /system/.restricted/project_upgrades.log looks like this (execution start/end date/times would be different, but durations must match):
[2021-04-30 18:23:08] ===  ===

# r4: Initial Project Task (#TASK_ID)
SELECT SLEEP(2); ... OK (1)
Duration: 2s (from 2021-04-30 18:23:08 to 2021-04-30 18:23:10)
ERROR; ... FAILED
SQL Error #1064: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'ERROR' at line 1

Total SQL Duration: 2s

Diff Detail

Repository
rINP In-Portal
Branch
/in-portal/branches/5.2.x
Lint
Lint ErrorsExcuse: Not fixing issues, that executed prior to made changes.
SeverityLocationCodeMessage
Errorcore/units/helpers/deployment_helper.php:524PHPCS.E.CodingStandard.WhiteSpace.ControlStructureSpacing.SpaceBeforeCloseBraceCodingStandard.WhiteSpace.ControlStructureSpacing.SpaceBeforeCloseBrace
Errorcore/units/helpers/deployment_helper.php:524PHPCS.E.CodingStandard.WhiteSpace.ControlStructureSpacing.SpacingAfterOpenBraceCodingStandard.WhiteSpace.ControlStructureSpacing.SpacingAfterOpenBrace
Errorcore/units/helpers/deployment_helper.php:526PHPCS.E.Generic.Files.LineLength.MaxExceededGeneric.Files.LineLength.MaxExceeded
Unit
No Unit Test Coverage
Build Status
Buildable 1041
Build 1041: arc lint + arc unit

Event Timeline

alex created this revision.Dec 23 2020, 9:16 AM
alex requested review of this revision.Dec 23 2020, 9:16 AM
alex edited the test plan for this revision. (Show Details)Dec 23 2020, 9:21 AM
alex added a project: Restricted Project.
alex edited the test plan for this revision. (Show Details)Dec 28 2020, 7:43 AM
alex updated this revision to Diff 957.Dec 28 2020, 7:52 AM
alex edited the test plan for this revision. (Show Details)

Fixed incorrect minute display (was shown number of seconds instead of number of minutes).

alex edited the test plan for this revision. (Show Details)Dec 28 2020, 9:01 AM
alex updated this revision to Diff 958.Dec 28 2020, 9:03 AM

Show total SQL execution time. Show SQL execution time in different color based on it's speed (<1 min, <5 min, longer).

erik accepted this revision.Feb 19 2021, 3:50 AM
This revision is now accepted and ready to land.Feb 19 2021, 3:50 AM
alex planned changes to this revision.Apr 30 2021, 9:42 AM

Totals are now shown after an SQL error.

alex updated this revision to Diff 1013.Apr 30 2021, 10:28 AM

Adding support for showing total SQL runtimes on error

This revision is now accepted and ready to land.Apr 30 2021, 10:28 AM
alex requested review of this revision.Apr 30 2021, 10:57 AM
alex edited the test plan for this revision. (Show Details)
alex edited the test plan for this revision. (Show Details)
erik accepted this revision.Jun 17 2021, 5:39 AM
This revision is now accepted and ready to land.Jun 17 2021, 5:39 AM
alex retitled this revision from INP-1794 - Show database query execution times durning deployment to INP-1794 - Show database query execution times during deployment.Jul 8 2022, 9:39 AM
This revision was landed with ongoing or failed builds.Jul 8 2022, 9:39 AM
This revision was automatically updated to reflect the committed changes.