Expose time spent collecting cycles in gc_status() #11523

arnaud-lb · 2023-06-24T14:52:38Z

This adds the following new entries to the gc_status() result:

application_time: Total application time (including collector_time)
collector_time: Time spend collecting cycles (including destructor_time and free_time)
destructor_time: Time spend executing destructors during cycle collection
free_time: Time spend freeing values during cycle collection

Times have nanoseconds resolution and use a monotonic clock. They are exposed as a number of seconds in floats, because the int type may be too small for nanoseconds depending on the platform.

application_time could be computed with hrtime(true) - $_SERVER['REQUEST_TIME_FLOAT'], but it seems useful to still expose it because $_SERVER['REQUEST_TIME_FLOAT'] is not monotonic.

sebastianbergmann · 2023-06-24T15:18:14Z

I cannot comment on the implementation, but this looks like what I asked for in #11327. Thank you for working on this!

mvorisek · 2023-06-24T22:29:59Z

Zend/zend_builtin_functions.c

@@ -148,6 +148,12 @@ ZEND_FUNCTION(gc_status)
 	add_assoc_long_ex(return_value, "threshold", sizeof("threshold")-1, (long)status.threshold);
 	add_assoc_long_ex(return_value, "buffer_size", sizeof("buffer_size")-1, (long)status.buf_size);
 	add_assoc_long_ex(return_value, "roots", sizeof("roots")-1, (long)status.num_roots);
+
+	/* Using double because zend_long may be too small on some platforms */
+	add_assoc_double_ex(return_value, "application_time", sizeof("application_time")-1, (double) status.application_time / ZEND_NANO_IN_SEC);


the init size above should be updated

also are/can these strings be interned for better perf?

what is the time measurement and gc_status() itself overhead?

I've updated the initial array size, thank you.

Regarding the time measurement overhead:

The synthetic benchmarks here and here show no significant overhead over multiple runs. The number of 10k nodes was chosen because this is the default GC threshold. Applications will typically have more nodes to scan, and their measurement_overhead/actual_work ratio will be lower.

I've seen no significant overhead on a long running application.

Regarding the overhead on gc_status() itself, it would matter if the function was called a high number of times during a request. Do you think it will be the case?

Regarding the overhead on gc_status() itself, it would matter if the function was called a high number of times during a request. Do you think it will be the case?

In PHPUnit 10, gc_status() is called for each event that is emitted. This is "a lot", but IMO perfectly fine in a development context.

I see no slowdown on the PHPUnit 10 test suite. However, gc_status() was called only 128 times. Is there a configuration that would cause more events to be triggered?

I was looking at the wrong file: gc_status() is actually called more than 19k times during the test suite and the changes in this PR caused no slowdown.

PHPUnit's test suite (main branch) currently has 2845 tests. For each test, multiple events are emitted. For each event, gc_status() is called. I am confused that you only see 128 calls.

beberlei · 2023-06-25T11:29:09Z

Zend/zend_time.h

+
+#define ZEND_NANO_IN_SEC 1000000000
+
+typedef uint64_t zend_time_t;


I would prefer this name to keep hr, since this clearly helps to identify the underlying abstraction used.

So zend_hrtime_t maybe, including names of the files etc

Agreed that zend_time is too general. I've renamed to zend_hrtime. Thank you!

iluuu1994 · 2023-06-26T13:10:03Z

ext/standard/hrtime.h

@@ -1,56 +0,0 @@
-/*


Do we need to move this? It should be fine to include an ext/standard header, as standard is a required extension.

It's not absolutely necessary, but it felt right to not have Zend/ depend on ext/ (for no particular reason other than Zend/ being a lower layer than ext/)

Moving code has a few disadvantages:

It makes reviewing harder, because it's difficult to determine what code is new and what code was just moved. Sometimes small changes can sneak into moved code too, which is very hard to catch without using a diff tool.

It creates merge conflicts when merging changes to the moved code. This is more of a problem for us than a "standard" code base because we have 3-4 active branches.

It breaks git blame.

Of course, not refactoring also has downsides, e.g. leading to big, messy files, or making things hard to find.

I don't mind either way, you can decide what you see fit.

I agree with your points. In this case I will retain the relocation of the code because, since I've also moved most of it from the .c to the .h for inlining purposes, keeping it in ext/ would not cancel all of these disadvantages.

iluuu1994 · 2023-06-26T13:21:41Z

Zend/zend_gc.c

@@ -439,6 +445,9 @@ static void gc_globals_ctor_ex(zend_gc_globals *gc_globals)

 	gc_globals->gc_runs = 0;
 	gc_globals->collected = 0;
+	gc_globals->collector_time = 0;


Is setting activated_at not desired here?

iluuu1994 · 2023-06-26T13:30:10Z

Zend/zend_gc.h

@@ -24,6 +24,8 @@
 # define GC_BENCH 0
 #endif

+#include "zend_hrtime.h"


Nit: We usually put includes first.

UPGRADING

dstogov

I don't see big problems.
The overhead of the patch is minimal and the collected information may be useful.

morrisonlevi · 2023-07-10T16:21:51Z

Zend/zend_hrtime.c

+
+#endif
+
+zend_result zend_startup_hrtime(void)


The return value is unused and isn't marked as ZEND_API. Any reason it shouldn't be void zend_startup_hrtime(void)?

This was existing code I moved from ext/standard/hrtime.c, and I tried to limit the amount of changes. But you are right, the return value is unnecessary, so I've removed it.

morrisonlevi · 2023-07-10T16:26:15Z

Zend/zend_hrtime.h

+
+#endif
+
+#define ZEND_NANO_IN_SEC 1000000000


This would avoid the need to cast this value:

Suggested change

#define ZEND_NANO_IN_SEC 1000000000

#define ZEND_NANO_IN_SEC UINT64_C(1000000000)

morrisonlevi · 2023-07-10T16:28:30Z

Zend/zend_hrtime.h

+	return (zend_hrtime_t)mach_absolute_time() * zend_hrtime_timerlib_info.numer / zend_hrtime_timerlib_info.denom;
+#elif ZEND_HRTIME_PLATFORM_POSIX
+	struct timespec ts = { .tv_sec = 0, .tv_nsec = 0 };
+	if (0 == clock_gettime(CLOCK_MONOTONIC, &ts)) {


I would expect branch predictors to handle this well, but I don't think this could hurt in this case:

Suggested change

if (0 == clock_gettime(CLOCK_MONOTONIC, &ts)) {

if (EXPECTED(0 == clock_gettime(CLOCK_MONOTONIC, &ts))) {

* up/master: (571 commits) Expose time spent collecting cycles in gc_status() (php#11523) Warn when fpm socket was not registered on the expected path Implement DOMElement::id Fix ? Implement DOMParentNode::replaceChildren() Implement DOMElement::className RFC: Deprecate remains of string evaluated code assertions (php#11671) Prevent decimal int precision loss in number_format() Implement DOMNode::getRootNode() Implement DOMElement::getAttributeNames() Refactor dom_node_node_name_read() to avoid double allocation Handle fragments consisting out of multiple children without a single root correctly Avoid allocations in DOMElement::getAttribute() Avoid string allocation in dom_get_dom1_attribute() for as long as possible Fix use-of-uninitialized-value when calling php_posix_stream_get_fd (php#11694) Reorder list construction in the function php_intpow10 (php#11683) proc_open: Use posix_spawn(3) interface on systems where it is profitable zend_gdb disable gdb detection for FreeBSD < 11. Fix iface const visibility variance check Fix missing iface class const inheritance type check ...

arnaud-lb added 2 commits June 24, 2023 16:36

Move php_hrtime_current() to zend_monotonic_time()

03fa600

Expose time spend collecting cycles in gc_status()

01653bf

github-actions bot added Category: Build System Category: Engine Extension: standard labels Jun 24, 2023

arnaud-lb added the Category: GC label Jun 24, 2023

arnaud-lb requested a review from sebastianbergmann June 24, 2023 14:53

mvorisek reviewed Jun 24, 2023

View reviewed changes

arnaud-lb added 2 commits June 25, 2023 12:52

Return failure

eba988b

Update initial array size

41f3252

beberlei reviewed Jun 25, 2023

View reviewed changes

arnaud-lb added 5 commits June 25, 2023 14:03

Rename zend_time -> zend_hrtime

c7fc79e

Fix windows build

92c6080

Actually rename

5e514e6

UPGRADING

c6c9a9d

Fix windows build

4e8c2ed

iluuu1994 reviewed Jun 26, 2023

View reviewed changes

arnaud-lb added 2 commits June 27, 2023 11:20

Initialize activated_at in globals ctors

5d73e31

Includes first

f580e4d

sebastianbergmann linked an issue Jun 27, 2023 that may be closed by this pull request

Expose time spent collecting cycles in gc_status() #11327

Closed

sebastianbergmann reviewed Jun 27, 2023

View reviewed changes

UPGRADING Outdated Show resolved Hide resolved

sebastianbergmann reviewed Jun 27, 2023

View reviewed changes

UPGRADING Outdated Show resolved Hide resolved

sebastianbergmann reviewed Jun 27, 2023

View reviewed changes

UPGRADING Outdated Show resolved Hide resolved

sebastianbergmann added a commit to sebastianbergmann/phpunit that referenced this pull request Jun 27, 2023

Use garbage collector information introduced in php/php-src#11523

f37f425

sebastianbergmann added a commit to sebastianbergmann/phpunit that referenced this pull request Jun 27, 2023

Use garbage collector information introduced in php/php-src#11523

ba90e5b

sebastianbergmann added a commit to sebastianbergmann/phpunit that referenced this pull request Jun 27, 2023

Use garbage collector information introduced in php/php-src#11523

7a30ae4

sebastianbergmann mentioned this pull request Jun 27, 2023

Add more garbage collector details to event telemetry sebastianbergmann/phpunit#5431

Closed

UPGRADING: typos

3002416

sebastianbergmann added a commit to sebastianbergmann/phpunit that referenced this pull request Jun 28, 2023

Use garbage collector information introduced in php/php-src#11523

0450a85

arnaud-lb marked this pull request as ready for review June 28, 2023 09:35

arnaud-lb requested review from dstogov and bukka as code owners June 28, 2023 09:35

dstogov approved these changes Jul 3, 2023

View reviewed changes

sebastianbergmann added a commit to sebastianbergmann/phpunit that referenced this pull request Jul 10, 2023

Use garbage collector information introduced in php/php-src#11523

4514579

morrisonlevi reviewed Jul 10, 2023

View reviewed changes

sebastianbergmann and others added 2 commits July 11, 2023 07:41

Merge branch 'master' into gc-timing

82c5be3

Review

0713de3

arnaud-lb merged commit d073193 into php:master Jul 16, 2023
12 checks passed

sebastianbergmann added a commit to sebastianbergmann/phpunit that referenced this pull request Jul 16, 2023

Use garbage collector information introduced in php/php-src#11523

e5fdf77

sebastianbergmann mentioned this pull request Jul 16, 2023

New elements in array returned by gc_status() vimeo/psalm#10022

Closed

sebastianbergmann added a commit to sebastianbergmann/phpunit that referenced this pull request Jul 18, 2023

Use garbage collector information introduced in php/php-src#11523

c9f5e87

sebastianbergmann added a commit to sebastianbergmann/phpunit that referenced this pull request Jul 18, 2023

Use garbage collector information introduced in php/php-src#11523

0abe06b

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Expose time spent collecting cycles in gc_status() #11523

Expose time spent collecting cycles in gc_status() #11523

arnaud-lb commented Jun 24, 2023 •

edited

Loading

sebastianbergmann commented Jun 24, 2023

mvorisek Jun 24, 2023

arnaud-lb Jun 25, 2023

sebastianbergmann Jun 25, 2023

arnaud-lb Jun 25, 2023

arnaud-lb Jun 25, 2023

sebastianbergmann Jun 25, 2023

sebastianbergmann Jun 25, 2023

beberlei Jun 25, 2023

arnaud-lb Jun 25, 2023

iluuu1994 Jun 26, 2023

arnaud-lb Jun 26, 2023

iluuu1994 Jun 27, 2023

arnaud-lb Jun 27, 2023

iluuu1994 Jun 26, 2023

iluuu1994 Jun 26, 2023

dstogov left a comment

morrisonlevi Jul 10, 2023

arnaud-lb Jul 14, 2023

morrisonlevi Jul 10, 2023

morrisonlevi Jul 10, 2023


		#define ZEND_NANO_IN_SEC 1000000000

		typedef uint64_t zend_time_t;

	#define ZEND_NANO_IN_SEC 1000000000
	#define ZEND_NANO_IN_SEC UINT64_C(1000000000)

	if (0 == clock_gettime(CLOCK_MONOTONIC, &ts)) {
	if (EXPECTED(0 == clock_gettime(CLOCK_MONOTONIC, &ts))) {

Expose time spent collecting cycles in gc_status() #11523

Expose time spent collecting cycles in gc_status() #11523

Conversation

arnaud-lb commented Jun 24, 2023 • edited Loading

sebastianbergmann commented Jun 24, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dstogov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

arnaud-lb commented Jun 24, 2023 •

edited

Loading