Runtime analysis

Started by Neto prover 8 years ago2 messagesgeneral
Jump to latest
#1Neto pr
netoprbr9@gmail.com

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

#2Tom Lane
tgl@sss.pgh.pa.us
In reply to: Neto pr (#1)
Re: Runtime analysis

Neto pr <netoprbr9@gmail.com> writes:

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
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.

Your Xeon is probably a variable-speed chip; did you take measures to
freeze the CPU frequency? On my RHEL server, I generally can't get
very reproducible numbers from benchmarks unless I first do
"sudo cpupower frequency-set --governor performance"
because the default "ondemand" governor is too eager to ratchet down
the frequency. Things might be different on Debian though.

In multi-socket servers, NUMA effects across sockets can be a big
headache too.

regards, tom lane

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general