Skip to content

Expose time spent collecting cycles in gc_status() #11523

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 14 commits into from
Jul 16, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 10 additions & 2 deletions UPGRADING
Original file line number Diff line number Diff line change
Expand Up @@ -134,12 +134,20 @@ PHP 8.3 UPGRADE NOTES
========================================

- Core:
. gc_status() has added the following 4 fields:
. gc_status() has added the following 8 fields:
"running" => bool
"protected" => bool
"full" => bool
"buffer_size" => int
See GH-9336
"application_time" => float: Total application time, in seconds (including
collector_time)
"collector_time" => float: Time spent collecting cycles, in seconds
(including destructor_time and free_time)
"destructor_time" => float: Time spent executing destructors during
cycle collection, in seconds
"free_time" => float: Time spent freeing values during cycle collection, in
seconds
See GH-9336, GH-11523
. class_alias() now supports creating an alias of an internal class.
. Setting `open_basedir` at runtime using `ini_set('open_basedir', ...);` no
longer accepts paths containing the parent directory (`..`). Previously,
Expand Down
4 changes: 4 additions & 0 deletions UPGRADING.INTERNALS
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,10 @@ PHP 8.3 INTERNALS UPGRADE NOTES
- zend_set_user_opcode_handler
- zend_ssa_inference
* Removed unused macros PHP_FNV1_32A_INIT and PHP_FNV1A_64_INIT. See GH-11114.
* ext/standard/hrtime.h was moved to Zend/zend_hrtime.h
* The prefix of the PHP_HRTIME_ macros was changed to ZEND_HRTIME_
* The HRTIME_AVAILABLE macro was renamed to ZEND_HRTIME_AVAILABLE
* The php_hrtime_current() function was renamed to zend_hrtime()
* _php_stream_dirent now has an extra d_type field that is used to store the
directory entry type. This can be used to avoid additional stat calls for
types when the type is already known.
Expand Down
22 changes: 19 additions & 3 deletions Zend/tests/gc_037.phpt
Original file line number Diff line number Diff line change
Expand Up @@ -12,8 +12,8 @@ gc_collect_cycles();
gc_collect_cycles();
var_dump(gc_status());
?>
--EXPECT--
array(8) {
--EXPECTF--
array(12) {
["running"]=>
bool(false)
["protected"]=>
Expand All @@ -30,8 +30,16 @@ array(8) {
int(16384)
["roots"]=>
int(1)
["application_time"]=>
float(%f)
["collector_time"]=>
float(%f)
["destructor_time"]=>
float(%f)
["free_time"]=>
float(%f)
}
array(8) {
array(12) {
["running"]=>
bool(false)
["protected"]=>
Expand All @@ -48,4 +56,12 @@ array(8) {
int(16384)
["roots"]=>
int(0)
["application_time"]=>
float(%f)
["collector_time"]=>
float(%f)
["destructor_time"]=>
float(%f)
["free_time"]=>
float(%f)
}
12 changes: 10 additions & 2 deletions Zend/tests/gc_045.phpt
Original file line number Diff line number Diff line change
Expand Up @@ -45,8 +45,8 @@ for ($j = 0; $j < 10; $j++) {

var_dump(gc_status());
?>
--EXPECT--
array(8) {
--EXPECTF--
array(12) {
["running"]=>
bool(false)
["protected"]=>
Expand All @@ -63,4 +63,12 @@ array(8) {
int(16384)
["roots"]=>
int(10000)
["application_time"]=>
float(%f)
["collector_time"]=>
float(%f)
["destructor_time"]=>
float(%f)
["free_time"]=>
float(%f)
}
2 changes: 2 additions & 0 deletions Zend/zend.c
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,7 @@
#include "zend_fibers.h"
#include "zend_call_stack.h"
#include "zend_max_execution_timer.h"
#include "zend_hrtime.h"
#include "Optimizer/zend_optimizer.h"

static size_t global_map_ptr_last = 0;
Expand Down Expand Up @@ -899,6 +900,7 @@ void zend_startup(zend_utility_functions *utility_functions) /* {{{ */
fpsetmask(0);
#endif

zend_startup_hrtime();
zend_startup_strtod();
zend_startup_extensions_mechanism();

Expand Down
8 changes: 7 additions & 1 deletion Zend/zend_builtin_functions.c
Original file line number Diff line number Diff line change
Expand Up @@ -138,7 +138,7 @@ ZEND_FUNCTION(gc_status)

zend_gc_get_status(&status);

array_init_size(return_value, 8);
array_init_size(return_value, 16);

add_assoc_bool_ex(return_value, "running", sizeof("running")-1, status.active);
add_assoc_bool_ex(return_value, "protected", sizeof("protected")-1, status.gc_protected);
Expand All @@ -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);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Aha! :)

add_assoc_double_ex(return_value, "collector_time", sizeof("collector_time")-1, (double) status.collector_time / ZEND_NANO_IN_SEC);
add_assoc_double_ex(return_value, "destructor_time", sizeof("destructor_time")-1, (double) status.dtor_time / ZEND_NANO_IN_SEC);
add_assoc_double_ex(return_value, "free_time", sizeof("free_time")-1, (double) status.free_time / ZEND_NANO_IN_SEC);
}
/* }}} */

Expand Down
30 changes: 30 additions & 0 deletions Zend/zend_gc.c
Original file line number Diff line number Diff line change
Expand Up @@ -69,6 +69,7 @@
#include "zend.h"
#include "zend_API.h"
#include "zend_fibers.h"
#include "zend_hrtime.h"

#ifndef ZEND_GC_DEBUG
# define ZEND_GC_DEBUG 0
Expand Down Expand Up @@ -220,6 +221,11 @@ typedef struct _zend_gc_globals {
uint32_t gc_runs;
uint32_t collected;

zend_hrtime_t activated_at;
zend_hrtime_t collector_time;
zend_hrtime_t dtor_time;
zend_hrtime_t free_time;

#if GC_BENCH
uint32_t root_buf_length;
uint32_t root_buf_peak;
Expand Down Expand Up @@ -439,6 +445,10 @@ 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;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is setting activated_at not desired here?

gc_globals->dtor_time = 0;
gc_globals->free_time = 0;
gc_globals->activated_at = 0;

#if GC_BENCH
gc_globals->root_buf_length = 0;
Expand Down Expand Up @@ -479,6 +489,10 @@ void gc_reset(void)
GC_G(gc_runs) = 0;
GC_G(collected) = 0;

GC_G(collector_time) = 0;
GC_G(dtor_time) = 0;
GC_G(free_time) = 0;

#if GC_BENCH
GC_G(root_buf_length) = 0;
GC_G(root_buf_peak) = 0;
Expand All @@ -488,6 +502,8 @@ void gc_reset(void)
GC_G(zval_marked_grey) = 0;
#endif
}

GC_G(activated_at) = zend_hrtime();
}

ZEND_API bool gc_enable(bool enable)
Expand Down Expand Up @@ -1469,6 +1485,8 @@ ZEND_API int zend_gc_collect_cycles(void)
bool should_rerun_gc = 0;
bool did_rerun_gc = 0;

zend_hrtime_t start_time = zend_hrtime();

rerun_gc:
if (GC_G(num_roots)) {
int count;
Expand All @@ -1482,6 +1500,7 @@ ZEND_API int zend_gc_collect_cycles(void)
stack.next = NULL;

if (GC_G(gc_active)) {
GC_G(collector_time) += zend_hrtime() - start_time;
return 0;
}

Expand Down Expand Up @@ -1561,6 +1580,7 @@ ZEND_API int zend_gc_collect_cycles(void)
*
* The root buffer might be reallocated during destructors calls,
* make sure to reload pointers as necessary. */
zend_hrtime_t dtor_start_time = zend_hrtime();
idx = GC_FIRST_ROOT;
while (idx != end) {
current = GC_IDX2PTR(idx);
Expand All @@ -1582,11 +1602,13 @@ ZEND_API int zend_gc_collect_cycles(void)
}
idx++;
}
GC_G(dtor_time) += zend_hrtime() - dtor_start_time;

if (GC_G(gc_protected)) {
/* something went wrong */
zend_get_gc_buffer_release();
zend_fiber_switch_unblock();
GC_G(collector_time) += zend_hrtime() - start_time;
return 0;
}
}
Expand All @@ -1595,6 +1617,7 @@ ZEND_API int zend_gc_collect_cycles(void)

/* Destroy zvals. The root buffer may be reallocated. */
GC_TRACE("Destroying zvals");
zend_hrtime_t free_start_time = zend_hrtime();
idx = GC_FIRST_ROOT;
while (idx != end) {
current = GC_IDX2PTR(idx);
Expand Down Expand Up @@ -1645,6 +1668,8 @@ ZEND_API int zend_gc_collect_cycles(void)
current++;
}

GC_G(free_time) += zend_hrtime() - free_start_time;

zend_fiber_switch_unblock();

GC_TRACE("Collection finished");
Expand All @@ -1666,6 +1691,7 @@ ZEND_API int zend_gc_collect_cycles(void)
finish:
zend_get_gc_buffer_release();
zend_gc_root_tmpvars();
GC_G(collector_time) += zend_hrtime() - start_time;
return total_count;
}

Expand All @@ -1679,6 +1705,10 @@ ZEND_API void zend_gc_get_status(zend_gc_status *status)
status->threshold = GC_G(gc_threshold);
status->buf_size = GC_G(buf_size);
status->num_roots = GC_G(num_roots);
status->application_time = zend_hrtime() - GC_G(activated_at);
status->collector_time = GC_G(collector_time);
status->dtor_time = GC_G(dtor_time);
status->free_time = GC_G(free_time);
}

ZEND_API zend_get_gc_buffer *zend_get_gc_buffer_create(void) {
Expand Down
6 changes: 6 additions & 0 deletions Zend/zend_gc.h
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,8 @@
#ifndef ZEND_GC_H
#define ZEND_GC_H

#include "zend_hrtime.h"

#ifndef GC_BENCH
# define GC_BENCH 0
#endif
Expand All @@ -35,6 +37,10 @@ typedef struct _zend_gc_status {
uint32_t threshold;
uint32_t buf_size;
uint32_t num_roots;
zend_hrtime_t application_time;
zend_hrtime_t collector_time;
zend_hrtime_t dtor_time;
zend_hrtime_t free_time;
} zend_gc_status;

ZEND_API extern int (*gc_collect_cycles)(void);
Expand Down
70 changes: 70 additions & 0 deletions Zend/zend_hrtime.c
Original file line number Diff line number Diff line change
@@ -0,0 +1,70 @@
/*
+----------------------------------------------------------------------+
| Copyright (c) The PHP Group |
+----------------------------------------------------------------------+
| This source file is subject to version 3.01 of the PHP license, |
| that is bundled with this package in the file LICENSE, and is |
| available through the world-wide-web at the following url: |
| https://www.php.net/license/3_01.txt |
| If you did not receive a copy of the PHP license and are unable to |
| obtain it through the world-wide-web, please send a note to |
| license@php.net so we can mail you a copy immediately. |
+----------------------------------------------------------------------+
| Author: Niklas Keller <kelunik@php.net> |
| Author: Anatol Belski <ab@php.net> |
+----------------------------------------------------------------------+
*/

#include "zend.h"
#include "zend_hrtime.h"

/* This file reuses code parts from the cross-platform timer library
Public Domain - 2011 Mattias Jansson / Rampant Pixels */

#if ZEND_HRTIME_PLATFORM_POSIX

# include <unistd.h>
# include <time.h>
# include <string.h>

#elif ZEND_HRTIME_PLATFORM_WINDOWS

# define WIN32_LEAN_AND_MEAN

double zend_hrtime_timer_scale = .0;

#elif ZEND_HRTIME_PLATFORM_APPLE

# include <mach/mach_time.h>
# include <string.h>
mach_timebase_info_data_t zend_hrtime_timerlib_info = {
.numer = 0,
.denom = 1,
};

#elif ZEND_HRTIME_PLATFORM_HPUX

# include <sys/time.h>

#elif ZEND_HRTIME_PLATFORM_AIX

# include <sys/time.h>
# include <sys/systemcfg.h>

#endif

void zend_startup_hrtime(void)
{
#if ZEND_HRTIME_PLATFORM_WINDOWS

LARGE_INTEGER tf = {0};
if (QueryPerformanceFrequency(&tf) || 0 != tf.QuadPart) {
zend_hrtime_timer_scale = (double)ZEND_NANO_IN_SEC / (zend_hrtime_t)tf.QuadPart;
}

#elif ZEND_HRTIME_PLATFORM_APPLE

mach_timebase_info(&zend_hrtime_timerlib_info);

#endif
}
Loading