[GENERAL] Runtime analysis - Mailing list pgsql-general

From Neto pr
Subject [GENERAL] Runtime analysis
Date
Msg-id CA+TZvY+PayZ3fCScKYw8=c6bx6MFpi6VZ3SJLfMFU8p7myOzxQ@mail.gmail.com
Whole thread Raw
Responses Re: [GENERAL] Runtime analysis
List pgsql-general
Hello All,
I was measuring the execution time of 18 queries from the TPC-H benchmark.
I run 10 times each query using the EXPLAIN ANALYZE command and store the times in a table called control_tab.

To record the times, I have a java program that does the whole process as follows:

Step 1: Insert into Tab_control values ​​(query_No, start_time) of query x
Step 2: Run the EXPLAIN ANALYZE command (inside Java)
Step 3: Update to save the final time of the query x and also the execution plan obtained.

After the 10th execution, I restart the DBMS and delete the cache this way:

   /etc/init.d/pgsql stop
   sync
   echo 3> / proc / sys / vm / drop_caches
   /etc/init.d/pgsql start

I expected that the first run would always take longer than the others because of not having cached data, but look what happened:
  • in 6 cases the first execution was more faster than all executions.
  • in 2 cases only, the first exececution was more slower than all executions

See at the end of the email, which had cases that the 1nd execution was 56% more faster than the 2nd execution.

If anyone has any suspicion or explanation,  why in some cases the first execution can be faster than the others, please reply to this email.

Note: My server is dedicated to the DBMS and during the test it did not have concurrent query executions.
The programs that were running at the time of the executions believe that they did not influence, because during the tests were little used, they are: web browser, libreoffice calc, Java eclipse, DBeaver, Konsole.
The features of the server are: Postgresql 10, 4 GB Ram, Xeon 2.8GHz / 4-core, S.O Debian 8.
If someone wants to see the execution plans and other information the worksheet with results is at the following link:
https://sites.google.com/site/eletrolareshop/repository/Result_80gb-SSD-10_exec_v4.ods

query 52 = 2, 53 = 3 on Tpch benchmark...
QUERY NoBEGIN TIMEEND TIMETIME SPENT


522017-11-02 20:44:332017-11-02 20:48:1100:03:381ª Execution was faster 56.6% than the 2ª
522017-11-02 20:48:112017-11-02 20:56:3400:08:22


522017-11-02 20:56:342017-11-02 21:06:1900:09:45


522017-11-02 21:06:192017-11-02 21:16:5200:10:32


522017-11-02 21:16:522017-11-02 21:28:0000:11:07


522017-11-02 21:28:002017-11-02 21:39:2900:11:29


522017-11-02 21:39:292017-11-02 21:50:5900:11:29


522017-11-02 21:50:592017-11-02 22:02:2300:11:23


522017-11-02 22:02:232017-11-02 22:13:4000:11:17


522017-11-02 22:13:402017-11-02 22:25:1100:11:31









532017-11-02 22:25:202017-11-02 22:48:1500:22:54


532017-11-02 22:48:152017-11-02 23:08:3600:20:20


532017-11-02 23:08:362017-11-02 23:26:5000:18:13


532017-11-02 23:26:502017-11-02 23:46:1600:19:26


532017-11-02 23:46:162017-11-03 00:05:3700:19:20


532017-11-03 00:05:372017-11-03 00:25:4200:20:05


532017-11-03 00:25:422017-11-03 00:46:1000:20:27


532017-11-03 00:46:102017-11-03 01:03:0500:16:55


532017-11-03 01:03:052017-11-03 01:19:5500:16:49


532017-11-03 01:19:552017-11-03 01:37:1200:17:17









542017-11-03 01:37:202017-11-03 01:45:0800:07:47


542017-11-03 01:45:082017-11-03 01:53:0000:07:51


542017-11-03 01:53:002017-11-03 02:00:5000:07:50


542017-11-03 02:00:502017-11-03 02:08:4300:07:52


542017-11-03 02:08:432017-11-03 02:16:3400:07:51


542017-11-03 02:16:342017-11-03 02:24:2400:07:50


542017-11-03 02:24:242017-11-03 02:32:1500:07:50


542017-11-03 02:32:152017-11-03 02:40:0400:07:49


542017-11-03 02:40:042017-11-03 02:47:5100:07:46


542017-11-03 02:47:512017-11-03 02:55:4000:07:48









552017-11-03 02:55:472017-11-03 03:19:2700:23:39


552017-11-03 03:19:272017-11-03 03:43:1200:23:45


552017-11-03 03:43:122017-11-03 04:08:0400:24:51


552017-11-03 04:08:042017-11-03 04:31:5800:23:54


552017-11-03 04:31:582017-11-03 04:56:1300:24:15


552017-11-03 04:56:142017-11-03 05:20:5400:24:40


552017-11-03 05:20:542017-11-03 05:46:0700:25:13


552017-11-03 05:46:072017-11-03 06:11:3500:25:27


552017-11-03 06:11:352017-11-03 06:36:4300:25:07


552017-11-03 06:36:432017-11-03 07:03:1800:26:34









562017-11-03 07:03:262017-11-03 07:06:5700:03:311ª Execution was faster 4.1% than the2ª
562017-11-03 07:06:572017-11-03 07:10:3800:03:40


562017-11-03 07:10:382017-11-03 07:14:1800:03:40


562017-11-03 07:14:182017-11-03 07:17:5900:03:40


562017-11-03 07:17:592017-11-03 07:21:4100:03:42


562017-11-03 07:21:412017-11-03 07:25:2200:03:40


562017-11-03 07:25:222017-11-03 07:29:0200:03:40


562017-11-03 07:29:022017-11-03 07:32:4200:03:39


562017-11-03 07:32:422017-11-03 07:36:2200:03:40


562017-11-03 07:36:222017-11-03 07:40:0500:03:42









572017-11-03 07:40:122017-11-03 07:50:4800:10:36


572017-11-03 07:50:492017-11-03 08:01:2600:10:37


572017-11-03 08:01:262017-11-03 08:12:0500:10:38


572017-11-03 08:12:052017-11-03 08:22:1900:10:14


572017-11-03 08:22:192017-11-03 08:32:3500:10:15


572017-11-03 08:32:352017-11-03 08:43:0400:10:28


572017-11-03 08:43:042017-11-03 08:52:5700:09:53


572017-11-03 08:52:572017-11-03 09:02:5000:09:53


572017-11-03 09:02:502017-11-03 09:12:3800:09:47


572017-11-03 09:12:382017-11-03 09:22:5100:10:12









582017-11-03 09:22:582017-11-03 09:32:2200:09:24


582017-11-03 09:32:222017-11-03 09:41:4700:09:24


582017-11-03 09:41:472017-11-03 09:51:2700:09:39


582017-11-03 09:51:272017-11-03 10:00:2900:09:01


582017-11-03 10:00:292017-11-03 10:09:2100:08:52


582017-11-03 10:09:222017-11-03 10:18:0700:08:45


582017-11-03 10:18:082017-11-03 10:26:5700:08:49


582017-11-03 10:26:572017-11-03 10:35:5000:08:52


582017-11-03 10:35:502017-11-03 10:45:1400:09:23


582017-11-03 10:45:142017-11-03 10:54:2400:09:10









592017-11-03 10:54:332017-11-03 12:08:1601:13:42


592017-11-03 12:08:162017-11-03 13:23:4501:15:28


592017-11-03 13:23:452017-11-03 14:37:3401:13:49


592017-11-03 14:37:342017-11-03 15:50:3001:12:55


592017-11-03 15:50:302017-11-03 17:03:1101:12:40


592017-11-03 17:03:112017-11-03 18:15:4301:12:32


592017-11-03 18:15:432017-11-03 19:28:1701:12:33


592017-11-03 19:28:172017-11-03 20:41:3601:13:19


592017-11-03 20:41:362017-11-03 21:54:1601:12:39


592017-11-03 21:54:162017-11-03 23:07:0701:12:51









602017-11-03 23:07:162017-11-03 23:23:1000:15:531ª Execution was faster 0.2% than the2ª
602017-11-03 23:23:102017-11-03 23:39:2200:16:11


602017-11-03 23:39:222017-11-03 23:55:1200:15:50


602017-11-03 23:55:122017-11-04 00:11:3600:16:23


602017-11-04 00:11:362017-11-04 00:27:2000:15:43


602017-11-04 00:27:202017-11-04 00:42:5100:15:31


602017-11-04 00:42:512017-11-04 00:58:5800:16:07


602017-11-04 00:58:592017-11-04 01:15:3100:16:32


602017-11-04 01:15:312017-11-04 01:32:1300:16:41


602017-11-04 01:32:132017-11-04 01:49:4100:17:28









612017-11-04 01:49:492017-11-04 01:50:4800:00:59


612017-11-04 01:50:482017-11-04 01:51:4600:00:57


612017-11-04 01:51:462017-11-04 01:52:4400:00:57


612017-11-04 01:52:442017-11-04 01:53:4200:00:58


612017-11-04 01:53:422017-11-04 01:54:4000:00:57


612017-11-04 01:54:402017-11-04 01:55:3800:00:57


612017-11-04 01:55:382017-11-04 01:56:3500:00:57


612017-11-04 01:56:352017-11-04 01:57:3200:00:57


612017-11-04 01:57:322017-11-04 01:58:3000:00:57


612017-11-04 01:58:302017-11-04 01:59:2700:00:57









622017-11-04 01:59:342017-11-04 02:05:2800:05:53


622017-11-04 02:05:282017-11-04 02:11:2800:05:59


622017-11-04 02:11:282017-11-04 02:17:2700:05:59


622017-11-04 02:17:272017-11-04 02:23:2600:05:59


622017-11-04 02:23:262017-11-04 02:29:2600:06:00


622017-11-04 02:29:262017-11-04 02:35:2700:06:00


622017-11-04 02:35:272017-11-04 02:41:2600:05:59


622017-11-04 02:41:262017-11-04 02:47:2600:06:00


622017-11-04 02:47:262017-11-04 02:53:2500:05:58


622017-11-04 02:53:252017-11-04 02:59:2500:05:59









632017-11-04 02:59:322017-11-04 03:10:2000:10:481ª Execution was faster 14.1% than the2ª
632017-11-04 03:10:202017-11-04 03:22:5500:12:34


632017-11-04 03:22:552017-11-04 03:35:1100:12:16


632017-11-04 03:35:112017-11-04 03:48:1800:13:07


632017-11-04 03:48:182017-11-04 04:00:4100:12:22


632017-11-04 04:00:412017-11-04 04:13:1500:12:34


632017-11-04 04:13:152017-11-04 04:26:0200:12:47


632017-11-04 04:26:022017-11-04 04:38:1600:12:13


632017-11-04 04:38:162017-11-04 04:50:4400:12:27


632017-11-04 04:50:442017-11-04 05:02:5300:12:09









642017-11-04 05:03:012017-11-04 05:08:5500:05:531ª Execution was faster 1.7% than the2ª
642017-11-04 05:08:552017-11-04 05:14:5400:05:59


642017-11-04 05:14:542017-11-04 05:20:5400:05:59


642017-11-04 05:20:542017-11-04 05:26:5400:06:00


642017-11-04 05:26:542017-11-04 05:32:5500:06:00


642017-11-04 05:32:552017-11-04 05:38:5500:06:00


642017-11-04 05:38:552017-11-04 05:44:5700:06:01


642017-11-04 05:44:572017-11-04 05:50:5800:06:00


642017-11-04 05:50:582017-11-04 05:57:0000:06:01


642017-11-04 05:57:002017-11-04 06:03:0100:06:01









652017-11-04 06:03:092017-11-04 06:13:2200:10:13


652017-11-04 06:13:222017-11-04 06:24:0000:10:38


652017-11-04 06:24:002017-11-04 06:34:2300:10:22


652017-11-04 06:34:232017-11-04 06:45:0200:10:38


652017-11-04 06:45:022017-11-04 06:55:3800:10:35


652017-11-04 06:55:382017-11-04 07:05:5500:10:17


652017-11-04 07:05:562017-11-04 07:16:0300:10:07


652017-11-04 07:16:032017-11-04 07:26:5100:10:47


652017-11-04 07:26:512017-11-04 07:37:1700:10:25


652017-11-04 07:37:172017-11-04 07:47:3700:10:19









662017-11-04 07:47:442017-11-04 07:51:1200:03:28


662017-11-04 07:51:122017-11-04 07:54:4700:03:34


662017-11-04 07:54:472017-11-04 07:58:2200:03:34


662017-11-04 07:58:222017-11-04 08:01:3400:03:11


662017-11-04 08:01:342017-11-04 08:05:0200:03:28


662017-11-04 08:05:022017-11-04 08:08:2800:03:25


662017-11-04 08:08:282017-11-04 08:11:5400:03:25


662017-11-04 08:11:542017-11-04 08:15:1800:03:23


662017-11-04 08:15:182017-11-04 08:18:4900:03:31


662017-11-04 08:18:492017-11-04 08:22:2500:03:35









672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00


672017-11-04 08:22:322017-11-04 08:22:3200:00:00









682017-11-04 08:22:392017-11-04 08:29:3800:06:591ª Execution was faster 7.3% than the2ª
682017-11-04 08:29:382017-11-04 08:37:1100:07:32


682017-11-04 08:37:112017-11-04 08:44:4800:07:36


682017-11-04 08:44:482017-11-04 08:52:2500:07:37


682017-11-04 08:52:252017-11-04 09:00:0400:07:38


682017-11-04 09:00:042017-11-04 09:07:3900:07:35


682017-11-04 09:07:392017-11-04 09:15:0800:07:28


682017-11-04 09:15:082017-11-04 09:22:1400:07:05


682017-11-04 09:22:142017-11-04 09:29:1900:07:05


682017-11-04 09:29:192017-11-04 09:36:3000:07:11









702017-11-04 09:36:382017-11-04 10:15:1300:38:34


702017-11-04 10:15:132017-11-04 10:54:4500:39:32


702017-11-04 10:54:452017-11-04 11:33:4200:38:56


702017-11-04 11:33:422017-11-04 12:13:0800:39:25


702017-11-04 12:13:082017-11-04 12:52:1600:39:08


702017-11-04 12:52:162017-11-04 13:31:1300:38:56


702017-11-04 13:31:132017-11-04 14:10:4200:39:28


702017-11-04 14:10:422017-11-04 14:49:4100:38:59



best regards 
Neto

pgsql-general by date:

Previous
From: "David G. Johnston"
Date:
Subject: Re: [GENERAL] ERROR: invalid input syntax for integer: "INSERT"
Next
From: Marko Tiikkaja
Date:
Subject: Re: [GENERAL] A possible use case for: "INSERT .. ON CONFLICT DO SELECT [FOR ..]"