Runtime analysis

From: Neto pr <netoprbr9(at)gmail(dot)com>
To: pgsql-general(at)postgresql(dot)org
Subject: Runtime analysis
Date: 2017-11-05 12:49:18
Message-ID: CA+TZvY+PayZ3fCScKYw8=c6bx6MFpi6VZ3SJLfMFU8p7myOzxQ@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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 No* *BEGIN TIME* *END TIME* *TIME SPENT*

52 2017-11-02 20:44:33 2017-11-02 20:48:11 *00:03:38* *1ª Execution was
faster * 56.6 % than the 2ª
52 2017-11-02 20:48:11 2017-11-02 20:56:34 00:08:22

52 2017-11-02 20:56:34 2017-11-02 21:06:19 00:09:45

52 2017-11-02 21:06:19 2017-11-02 21:16:52 00:10:32

52 2017-11-02 21:16:52 2017-11-02 21:28:00 00:11:07

52 2017-11-02 21:28:00 2017-11-02 21:39:29 00:11:29

52 2017-11-02 21:39:29 2017-11-02 21:50:59 00:11:29

52 2017-11-02 21:50:59 2017-11-02 22:02:23 00:11:23

52 2017-11-02 22:02:23 2017-11-02 22:13:40 00:11:17

52 2017-11-02 22:13:40 2017-11-02 22:25:11 00:11:31

53 2017-11-02 22:25:20 2017-11-02 22:48:15 *00:22:54*

53 2017-11-02 22:48:15 2017-11-02 23:08:36 00:20:20

53 2017-11-02 23:08:36 2017-11-02 23:26:50 00:18:13

53 2017-11-02 23:26:50 2017-11-02 23:46:16 00:19:26

53 2017-11-02 23:46:16 2017-11-03 00:05:37 00:19:20

53 2017-11-03 00:05:37 2017-11-03 00:25:42 00:20:05

53 2017-11-03 00:25:42 2017-11-03 00:46:10 00:20:27

53 2017-11-03 00:46:10 2017-11-03 01:03:05 00:16:55

53 2017-11-03 01:03:05 2017-11-03 01:19:55 00:16:49

53 2017-11-03 01:19:55 2017-11-03 01:37:12 00:17:17

54 2017-11-03 01:37:20 2017-11-03 01:45:08 *00:07:47*

54 2017-11-03 01:45:08 2017-11-03 01:53:00 00:07:51

54 2017-11-03 01:53:00 2017-11-03 02:00:50 00:07:50

54 2017-11-03 02:00:50 2017-11-03 02:08:43 00:07:52

54 2017-11-03 02:08:43 2017-11-03 02:16:34 00:07:51

54 2017-11-03 02:16:34 2017-11-03 02:24:24 00:07:50

54 2017-11-03 02:24:24 2017-11-03 02:32:15 00:07:50

54 2017-11-03 02:32:15 2017-11-03 02:40:04 00:07:49

54 2017-11-03 02:40:04 2017-11-03 02:47:51 00:07:46

54 2017-11-03 02:47:51 2017-11-03 02:55:40 00:07:48

55 2017-11-03 02:55:47 2017-11-03 03:19:27 *00:23:39*

55 2017-11-03 03:19:27 2017-11-03 03:43:12 00:23:45

55 2017-11-03 03:43:12 2017-11-03 04:08:04 00:24:51

55 2017-11-03 04:08:04 2017-11-03 04:31:58 00:23:54

55 2017-11-03 04:31:58 2017-11-03 04:56:13 00:24:15

55 2017-11-03 04:56:14 2017-11-03 05:20:54 00:24:40

55 2017-11-03 05:20:54 2017-11-03 05:46:07 00:25:13

55 2017-11-03 05:46:07 2017-11-03 06:11:35 00:25:27

55 2017-11-03 06:11:35 2017-11-03 06:36:43 00:25:07

55 2017-11-03 06:36:43 2017-11-03 07:03:18 00:26:34

56 2017-11-03 07:03:26 2017-11-03 07:06:57 *00:03:31* *1ª Execution was
faster * 4.1 % than the2ª
56 2017-11-03 07:06:57 2017-11-03 07:10:38 00:03:40

56 2017-11-03 07:10:38 2017-11-03 07:14:18 00:03:40

56 2017-11-03 07:14:18 2017-11-03 07:17:59 00:03:40

56 2017-11-03 07:17:59 2017-11-03 07:21:41 00:03:42

56 2017-11-03 07:21:41 2017-11-03 07:25:22 00:03:40

56 2017-11-03 07:25:22 2017-11-03 07:29:02 00:03:40

56 2017-11-03 07:29:02 2017-11-03 07:32:42 00:03:39

56 2017-11-03 07:32:42 2017-11-03 07:36:22 00:03:40

56 2017-11-03 07:36:22 2017-11-03 07:40:05 00:03:42

57 2017-11-03 07:40:12 2017-11-03 07:50:48 *00:10:36*

57 2017-11-03 07:50:49 2017-11-03 08:01:26 00:10:37

57 2017-11-03 08:01:26 2017-11-03 08:12:05 00:10:38

57 2017-11-03 08:12:05 2017-11-03 08:22:19 00:10:14

57 2017-11-03 08:22:19 2017-11-03 08:32:35 00:10:15

57 2017-11-03 08:32:35 2017-11-03 08:43:04 00:10:28

57 2017-11-03 08:43:04 2017-11-03 08:52:57 00:09:53

57 2017-11-03 08:52:57 2017-11-03 09:02:50 00:09:53

57 2017-11-03 09:02:50 2017-11-03 09:12:38 00:09:47

57 2017-11-03 09:12:38 2017-11-03 09:22:51 00:10:12

58 2017-11-03 09:22:58 2017-11-03 09:32:22 *00:09:24*

58 2017-11-03 09:32:22 2017-11-03 09:41:47 00:09:24

58 2017-11-03 09:41:47 2017-11-03 09:51:27 00:09:39

58 2017-11-03 09:51:27 2017-11-03 10:00:29 00:09:01

58 2017-11-03 10:00:29 2017-11-03 10:09:21 00:08:52

58 2017-11-03 10:09:22 2017-11-03 10:18:07 00:08:45

58 2017-11-03 10:18:08 2017-11-03 10:26:57 00:08:49

58 2017-11-03 10:26:57 2017-11-03 10:35:50 00:08:52

58 2017-11-03 10:35:50 2017-11-03 10:45:14 00:09:23

58 2017-11-03 10:45:14 2017-11-03 10:54:24 00:09:10

59 2017-11-03 10:54:33 2017-11-03 12:08:16 *01:13:42*

59 2017-11-03 12:08:16 2017-11-03 13:23:45 01:15:28

59 2017-11-03 13:23:45 2017-11-03 14:37:34 01:13:49

59 2017-11-03 14:37:34 2017-11-03 15:50:30 01:12:55

59 2017-11-03 15:50:30 2017-11-03 17:03:11 01:12:40

59 2017-11-03 17:03:11 2017-11-03 18:15:43 01:12:32

59 2017-11-03 18:15:43 2017-11-03 19:28:17 01:12:33

59 2017-11-03 19:28:17 2017-11-03 20:41:36 01:13:19

59 2017-11-03 20:41:36 2017-11-03 21:54:16 01:12:39

59 2017-11-03 21:54:16 2017-11-03 23:07:07 01:12:51

60 2017-11-03 23:07:16 2017-11-03 23:23:10 *00:15:53* *1ª Execution was
faster * 0.2 % than the2ª
60 2017-11-03 23:23:10 2017-11-03 23:39:22 00:16:11

60 2017-11-03 23:39:22 2017-11-03 23:55:12 00:15:50

60 2017-11-03 23:55:12 2017-11-04 00:11:36 00:16:23

60 2017-11-04 00:11:36 2017-11-04 00:27:20 00:15:43

60 2017-11-04 00:27:20 2017-11-04 00:42:51 00:15:31

60 2017-11-04 00:42:51 2017-11-04 00:58:58 00:16:07

60 2017-11-04 00:58:59 2017-11-04 01:15:31 00:16:32

60 2017-11-04 01:15:31 2017-11-04 01:32:13 00:16:41

60 2017-11-04 01:32:13 2017-11-04 01:49:41 00:17:28

61 2017-11-04 01:49:49 2017-11-04 01:50:48 *00:00:59*

61 2017-11-04 01:50:48 2017-11-04 01:51:46 00:00:57

61 2017-11-04 01:51:46 2017-11-04 01:52:44 00:00:57

61 2017-11-04 01:52:44 2017-11-04 01:53:42 00:00:58

61 2017-11-04 01:53:42 2017-11-04 01:54:40 00:00:57

61 2017-11-04 01:54:40 2017-11-04 01:55:38 00:00:57

61 2017-11-04 01:55:38 2017-11-04 01:56:35 00:00:57

61 2017-11-04 01:56:35 2017-11-04 01:57:32 00:00:57

61 2017-11-04 01:57:32 2017-11-04 01:58:30 00:00:57

61 2017-11-04 01:58:30 2017-11-04 01:59:27 00:00:57

62 2017-11-04 01:59:34 2017-11-04 02:05:28 *00:05:53*

62 2017-11-04 02:05:28 2017-11-04 02:11:28 00:05:59

62 2017-11-04 02:11:28 2017-11-04 02:17:27 00:05:59

62 2017-11-04 02:17:27 2017-11-04 02:23:26 00:05:59

62 2017-11-04 02:23:26 2017-11-04 02:29:26 00:06:00

62 2017-11-04 02:29:26 2017-11-04 02:35:27 00:06:00

62 2017-11-04 02:35:27 2017-11-04 02:41:26 00:05:59

62 2017-11-04 02:41:26 2017-11-04 02:47:26 00:06:00

62 2017-11-04 02:47:26 2017-11-04 02:53:25 00:05:58

62 2017-11-04 02:53:25 2017-11-04 02:59:25 00:05:59

63 2017-11-04 02:59:32 2017-11-04 03:10:20 *00:10:48* *1ª Execution was
faster * 14.1 % than the2ª
63 2017-11-04 03:10:20 2017-11-04 03:22:55 00:12:34

63 2017-11-04 03:22:55 2017-11-04 03:35:11 00:12:16

63 2017-11-04 03:35:11 2017-11-04 03:48:18 00:13:07

63 2017-11-04 03:48:18 2017-11-04 04:00:41 00:12:22

63 2017-11-04 04:00:41 2017-11-04 04:13:15 00:12:34

63 2017-11-04 04:13:15 2017-11-04 04:26:02 00:12:47

63 2017-11-04 04:26:02 2017-11-04 04:38:16 00:12:13

63 2017-11-04 04:38:16 2017-11-04 04:50:44 00:12:27

63 2017-11-04 04:50:44 2017-11-04 05:02:53 00:12:09

64 2017-11-04 05:03:01 2017-11-04 05:08:55 *00:05:53* *1ª Execution was
faster * 1.7 % than the2ª
64 2017-11-04 05:08:55 2017-11-04 05:14:54 00:05:59

64 2017-11-04 05:14:54 2017-11-04 05:20:54 00:05:59

64 2017-11-04 05:20:54 2017-11-04 05:26:54 00:06:00

64 2017-11-04 05:26:54 2017-11-04 05:32:55 00:06:00

64 2017-11-04 05:32:55 2017-11-04 05:38:55 00:06:00

64 2017-11-04 05:38:55 2017-11-04 05:44:57 00:06:01

64 2017-11-04 05:44:57 2017-11-04 05:50:58 00:06:00

64 2017-11-04 05:50:58 2017-11-04 05:57:00 00:06:01

64 2017-11-04 05:57:00 2017-11-04 06:03:01 00:06:01

65 2017-11-04 06:03:09 2017-11-04 06:13:22 *00:10:13*

65 2017-11-04 06:13:22 2017-11-04 06:24:00 00:10:38

65 2017-11-04 06:24:00 2017-11-04 06:34:23 00:10:22

65 2017-11-04 06:34:23 2017-11-04 06:45:02 00:10:38

65 2017-11-04 06:45:02 2017-11-04 06:55:38 00:10:35

65 2017-11-04 06:55:38 2017-11-04 07:05:55 00:10:17

65 2017-11-04 07:05:56 2017-11-04 07:16:03 00:10:07

65 2017-11-04 07:16:03 2017-11-04 07:26:51 00:10:47

65 2017-11-04 07:26:51 2017-11-04 07:37:17 00:10:25

65 2017-11-04 07:37:17 2017-11-04 07:47:37 00:10:19

66 2017-11-04 07:47:44 2017-11-04 07:51:12 *00:03:28*

66 2017-11-04 07:51:12 2017-11-04 07:54:47 00:03:34

66 2017-11-04 07:54:47 2017-11-04 07:58:22 00:03:34

66 2017-11-04 07:58:22 2017-11-04 08:01:34 00:03:11

66 2017-11-04 08:01:34 2017-11-04 08:05:02 00:03:28

66 2017-11-04 08:05:02 2017-11-04 08:08:28 00:03:25

66 2017-11-04 08:08:28 2017-11-04 08:11:54 00:03:25

66 2017-11-04 08:11:54 2017-11-04 08:15:18 00:03:23

66 2017-11-04 08:15:18 2017-11-04 08:18:49 00:03:31

66 2017-11-04 08:18:49 2017-11-04 08:22:25 00:03:35

67 2017-11-04 08:22:32 2017-11-04 08:22:32 *00:00:00*

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

67 2017-11-04 08:22:32 2017-11-04 08:22:32 00:00:00

68 2017-11-04 08:22:39 2017-11-04 08:29:38 *00:06:59* *1ª Execution was
faster * 7.3 % than the2ª
68 2017-11-04 08:29:38 2017-11-04 08:37:11 00:07:32

68 2017-11-04 08:37:11 2017-11-04 08:44:48 00:07:36

68 2017-11-04 08:44:48 2017-11-04 08:52:25 00:07:37

68 2017-11-04 08:52:25 2017-11-04 09:00:04 00:07:38

68 2017-11-04 09:00:04 2017-11-04 09:07:39 00:07:35

68 2017-11-04 09:07:39 2017-11-04 09:15:08 00:07:28

68 2017-11-04 09:15:08 2017-11-04 09:22:14 00:07:05

68 2017-11-04 09:22:14 2017-11-04 09:29:19 00:07:05

68 2017-11-04 09:29:19 2017-11-04 09:36:30 00:07:11

70 2017-11-04 09:36:38 2017-11-04 10:15:13 *00:38:34*

70 2017-11-04 10:15:13 2017-11-04 10:54:45 00:39:32

70 2017-11-04 10:54:45 2017-11-04 11:33:42 00:38:56

70 2017-11-04 11:33:42 2017-11-04 12:13:08 00:39:25

70 2017-11-04 12:13:08 2017-11-04 12:52:16 00:39:08

70 2017-11-04 12:52:16 2017-11-04 13:31:13 00:38:56

70 2017-11-04 13:31:13 2017-11-04 14:10:42 00:39:28

70 2017-11-04 14:10:42 2017-11-04 14:49:41 00:38:59

best regards
Neto

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Marko Tiikkaja 2017-11-05 15:06:08 Re: A possible use case for: "INSERT .. ON CONFLICT DO SELECT [FOR ..]"
Previous Message David G. Johnston 2017-11-05 04:05:08 Re: ERROR: invalid input syntax for integer: "INSERT"