Xdebug 2.3: Improvements to Tracing

This is the fifth article in a series about new features in Xdebug 2.3, which was first released on February 22nd.

In this instalment we are going to have a look at the additions to the trace file functionality. Trace files are a way to document every function call, and if you enable it, variable assignment and function's return values — including when these functions were called, and how much memory PHP was using at the moment of function entry (and exit).

Xdebug 2.3 adds a new type of parameter rendering for stack traces and function traces through the xdebug.collect_params setting. Existing options are 1/2 for just the variable type, 3 for a string description, and 4 for a string description and a variable name. Xdebug 2.3 now also features a base64 encoded serialized representation of the variable's contents (option 5). Which means that the following lines:

$a = array(1, "foo", M_PI);
var_dump($a);

show up in the following 5 ways with different variations of the xdebug.collect_params setting:

  1. var_dump(array(3))

  2. var_dump(array(3))

  3. var_dump(array (0 => 1, 1 => 'foo', 2 => 3.1415926535898))

  4. var_dump(array (0 => 1, 1 => 'foo', 2 => 3.1415926535898))

  5. var_dump(YTozOntpOjA7aToxO2k6MTtzOjM6ImZvbyI7aToyO2Q6My4xNDE1OTI2NTM1ODk3OTMxO30=)

This is probably more useful with the computerized trace files that are easier to parse.


In Xdebug 2.3, normal (human readable) trace files now also show the time index and memory usage for function exit lines. Function exit lines are generated when xdebug.collect_return is set to 1. Which means that with with Xdebug 2.2 you would see:

TRACE START [2015-03-28 18:48:39]
  0.0008     275928   -> test1() …/closure-trace.phpt:27
  0.0008     276848     -> {closure:…/closure-trace.phpt:20-22}() …/closure-trace.phpt:24
  0.0009     277168       -> strlen() …/closure-trace.phpt:21
                           >=> 3
                         >=> 3
                       >=> NULL
  0.0010     276056   -> xdebug_stop_trace() …/closure-trace.phpt:28
  0.0010     276184
TRACE END   [2015-03-28 18:48:39]

But in Xdebug 2.3 you instead see:

TRACE START [2015-03-28 18:48:45]
  0.0008     269144   -> test1() …/closure-trace.phpt:27
  0.0009     270096     -> {closure:…/closure-trace.phpt:20-22}() …/closure-trace.phpt:24
  0.0009     270336       -> strlen() …/closure-trace.phpt:21
  0.0010     270504        >=> 3
  0.0010     270216      >=> 3
  0.0010     269264    >=> NULL
  0.0011     269264   -> xdebug_stop_trace() …/closure-trace.phpt:28
  0.0011     269384
TRACE END   [2015-03-28 18:48:45]

This makes it easier to see how much time and memory a specific function call took, similarly to what already was shown for "computerized" trace files.


And lastly, the computerized format (xdebug.trace_format=1), has now support for showing return values as well. The return value is part of a new "frame" for a function.

Take the following invocation of PHP:

php -dxdebug.collect_params=0 -dxdebug.collect_return=1 \
        -dxdebug.trace_format=1 \
        -r '$a = array(1, "foo", M_PI); xdebug_start_trace("/tmp/trace"); echo
        serialize($a);' \
>/dev/null && cat /tmp/trace.xt

In Xdebug 2.2 this shows:

TRACE START [2015-03-29 00:08:34]
2    1    1    0.000417    267192
2    2    0    0.000547    266848    serialize   0   Command line code   1   1   array (0 => 1, 1 => 'foo', 2 => 3.1415926535898)
2    2    1    0.000626    267024
1    0    1    0.000695    266968
               0.000925    8536
TRACE END   [2015-03-29 00:08:34]

But Xdebug 2.3 has an extra "return frame" with the return value:

TRACE START [2015-03-29 00:10:11]
2    1    1    0.000462    263152
2    2    0    0.000520    262928    serialize   0   Command line code   1   1   array (0 => 1, 1 => 'foo', 2 => 3.1415926535898)
2    2    1    0.000594    263096
2    2    R                          'a:3:{i:0;i:1;i:1;s:3:"foo";i:2;d:3.1415926535897931;}'
1    0    1    0.000676    263040
               0.000881    8512
TRACE END   [2015-03-29 00:10:11]

Function 2 (the call to serialize) now has an entry frame (0) and exit frame (1) showing the time index and memory usage, as well as the new R frame showing the return value. Unlike human readable traces it is not on the same line as the exit frame because of backwards compatibility reasons.


Other parts in this series:

Shortlink

This article has a short URL available: http://drck.me/tracing23-bom

Comments

No comments yet

Xdebug 2.3: Improvements to Debugging

This is the fourth article in a series about new features in Xdebug 2.3, which was first released on February 22nd.

In this article we are looking at the improvements towards "remote" debugging.


The first improvement is the addition to view the values of user defined constants. In Xdebug this works by defining another context. Existing contexts are local variables, and super globals. In PhpStorm, they show up in the same "Variables" box:

Xdebug 2.3 defines a third context, "User defined constants". This new third context also shows up in PhpStorm's "Variables" box:

However, if you have lots of constants, that becomes annoying. Follow (or comment on) issue WI-21691 if you want to see this changed.

Other IDEs, such as Komodo, handle this by having a separate tab for constants:

It is actually clever enough to create a new tab for every new context that I come up with, as they haven't hard coded it.


Another new debugging feature is to be able to set an exception breakpoint on all exceptions, by using * as the exception name. Xdebug 2.3 also breaks on exception classes that are inherited from the ones you set a breakpoint on. With the following code:

<?php
class BaseException extends Exception {}
class ChildException extends BaseException {}

echo "start\n";

try
{
        echo "first try\n";
        throw new ChildException("No noes!");
}
catch ( ChildException $e )
{
        echo "eat it\n";
}

echo "end\n";
?>

And the following exception breakpoints configured in PhpStorm:

Xdebug will now interrupt the script when it hits line 11 because an exception breakpoint for both BaseException (the parent of the exception that we are throwing) and * are configured.


The third feature that I would like to highlight is related to the additions to debugging exceptions. Xdebug now includes the exception's error code in the reply to the IDE. However, it does not seem that PhpStorm allows me to see which exception it broke on, and what its message and error code are.

For now, you will have to do with the raw XML result (after formatting):

-> run -i 6
<?xml version="1.0" encoding="iso-8859-1"?>
<response
        xmlns="urn:debugger_protocol_v1"
        xmlns:xdebug="http://xdebug.org/dbgp/xdebug"
        command="run" transaction_id="6"
        status="break" reason="ok"
>
        <xdebug:message
                filename="file:///tmp/xdebug-dbgp-test.php" lineno="28"
                exception="FooBarException" code="43"
        >
                <![CDATA[this should still break]]>
        </xdebug:message>
</response>

I have created issue WI-26880 in their issue tracker as a feature request.


And the last thing that has changed with debugging in Xdebug 2.3 is that now Xdebug will try to log when you do not have sufficient permissions to create a socket. For example when you have SELinux turned on but not properly configured. The new message is:

E: No permission connecting to client. This could be SELinux related. :-(


Other parts in this series:

Shortlink

This article has a short URL available: http://drck.me/debugs23-bod

Comments

Awesome features, thanks for keeping Xdebug alive!

MongoDB 3.0 features: Big Polygon

MongoDB has had geospatial query support since MongoDB 1.4. In subsequent versions we have added a range of new features, such as GeoJSON in MongoDB 2.4. In this post I will cover a new feature in MongoDB 3.0 for searching polygons that are larger than a hemisphere.

Finding objects in a specific area (polygon) can be done with the $geoWithin operator as illustrated below:

<?php
$c = (new MongoClient())->demo->points;

$c->find( [
    'loc' => [
        '$geoWithin' => [
            'type' => 'Polygon',
            'coordinates' => [ [
                [ -0.91, 51.74 ],
                [ -0.91, 51.27 ],
                [  0.67, 51.27 ],
                [  0.67, 51.74 ],
                [ -0.91, 51.74 ]
            ] ]
        ]
    ]
] );
?>

The GeoJSON format, which we use in this query as argument to the $geoWithin operator, defines a polygon as an array of linear rings, which themselves are a list of coordinate pairs beginning and ending with the same point to form a closed ring. The first linear ring is required and defines the exterior boundary of the polygon. Subsequent rings, if specified, would define interior boundaries (i.e. holes) within the polygon.

As an image, the geometry in this query looks like:

The GeoJSON format specification does not give any meaning about the direction or winding of points. The application is left to determine which side of the geometry is the search area. Both of the following images are possible interpretations when just taking the GeoJSON specification into account:

The interpretation of which part forms the search area would of course provide very different results! Because GeoJSON does not address winding, sometimes applications make wrong decisions.

MongoDB deterministically chooses the area that is the "smallest of the two". For our query, it would consider the polygon that is shown first of the two interpretations shown above.

This logic works for most applications, but it falls apart when you want to find objects within a polygon that spans more than a hemisphere.

In the small example of London, you would certainly expect the smallest area, the one that covers London to be the search area. But when we consider this much larger polygon (a circle centred around 25°N, 90°E with a diameter of 115°), then it is not so obvious:

When the polygon is larger than a hemisphere, i.e. larger than half of the Earth's surface, the "smallest of the two" is actually the area we intended to exclude. From MongoDB 3.0 a custom coordinate reference system (CRS) is supported, which forces geospatial queries with a polygon search area to consider the direction of coordinates in deciding which side is the search area. Consistent with KML, and WKT/WKB, the search area is determined to be the area that is on the left hand side of the direction of points. MongoDB calls this "strict winding". With strict winding enabled through our custom CRS, the following two possibilities can be considered:

MongoDB's implementation of GeoJSON allows us to specify a custom coordinate reference system on any geometry object via a crs property. Currently MongoDB only supports our custom CRS, urn:x-mongodb:crs:strictwinding:EPSG:4326, to specify strict winding. In the future, MongoDB could also support others, such as UTM, the US National Grid, or the UK's Ordnance Survey National Grid. The addition of support for this crs property is called "Big Polygon support" in MongoDB.

In a query, our custom CRS would appear as an extra argument within the $geoWithin or $geoIntersects criteria, on the same level as type and coordinates:

<?php
$c = (new MongoClient())->demo->points;

$c->find( [
    'loc' => [
        '$geoWithin' => [
            'type' => 'Polygon',
            'coordinates' => [ [
                [ -0.91, 51.74 ],
                [ -0.91, 51.27 ],
                [  0.67, 51.27 ],
                [  0.67, 51.74 ],
                [ -0.91, 51.74 ]
            ] ],
            'crs' => [
                'type' => 'name',
                'properties' => [
                    'name' => 'urn:x-mongodb:crs:strictwinding:EPSG:4326'
                ]
            ]
        ]
    ]
] );
?>

The use of the custom CRS is only relevant when searching an area that is larger than a hemisphere. In most cases, the default "smallest of the two" behaviour will be sufficient and you will not need to specify a custom CRS.

Shortlink

This article has a short URL available: http://drck.me/bigpolygon-bo2

Comments

No comments yet

Xdebug 2.3: Munging errors

This is the third article in a series about new features in Xdebug 2.3, which was first released on February 22nd.

One of the first features I added to Xdebug was the interception of error messages, so that it was possible for me to include a stack trace. Xdebug 2.3 has a few additional settings to control the behaviour of interception.

First, we have the new xdebug.halt_level. This setting allows you to tell Xdebug to convert certain warnings into fatal errors. Due to the way how PHP works, you can currently only do this for E_WARNING, E_NOTICE, E_USER_WARNING, and E_USER_NOTICE.

Setting xdebug.halt_level to E_NOTICE | E_USER_NOTICE will make the following script not show Hi!:

<?php
ini_set('xdebug.halt_level', E_USER_NOTICE | E_NOTICE);
trigger_error("Testing");
echo "Hi!\n";
?>

Instead, it will show the call stack, and then abort the script:

Notice: Testing in - on line 3

Call Stack:
        0.0082     258480   1. {main}() -:0
        0.0085     259400   2. trigger_error() -:3

This feature was requested by Rob Allen, who also wrote about it.

The second related improvement is the addition of the xdebug.force_display_errors and xdebug.force_error_reporting settings. These php.ini only settings can be used to override PHP's display_errors and error_reporting settings. This is typically useful in a legacy code base where developers tried to be clever about not showing warnings, or for example turning of notices that now hamper developer - or upgrade efforts.

Take the following script:

<?php
ini_set("display_errors", 0);
trigger_error("two");
?>

When you run this with just php thescript.php, the output will be nothing (because you are hiding errors). Running the example script with php -d xdebug.force_display_errors=1 thescript.php, the output becomes:

Notice: two in /tmp/thescript.php on line 3

Call Stack:
        0.0002     261072   1. {main}() /tmp/thescript.php:0
        0.0002     261944   2. trigger_error() /tmp/thescript.php:3

The related setting xdebug.force_error_reporting acts at a bit mask to force certain errors to be shown. Even with error_reporting set to 0, the following script run with php -d xdebug.force_error_reporting /tmp/otherscript.php will still show the errors:

<?php
ini_set("error_reporting", E_ERROR | E_WARNING | E_USER_WARNING);
trigger_error("two", E_USER_NOTICE);
?>

With as output:

Notice: two in /tmp/otherscript.php on line 3

Call Stack:
        0.0002     261432   1. {main}() /tmp/otherscript.php:0
        0.0003     262352   2. trigger_error() /tmp/otherscript.php:3


Other parts in this series:

Shortlink

This article has a short URL available: http://drck.me/errors23-bns

Comments

Both features are awesome! No more die() debugging on strangely configured systems.

Xdebug 2.3: Enhanced xdebug_debug_zval()

This is the second article in a series about new features in Xdebug 2.3, which was first released on February 22nd.

xdebug_debug_zval() has been around for quite some time, to provide correct information about how PHP internally stores a variable. Unlike PHP's built in debug_zval_dump() function, it does not modify the variable information that it tries to show. This is because instead of passing in a variable, you pass in its name. Passing a variable into a function, can modify the various parameters that are associated with this variable, such as the is_ref and refcount fields.

xdebug_debug_zval() does not suffer from these inadvertent modifications, as you pass in the variable's name, and the function looks up the information about a variable in the symbol tables itself.

The difference becomes clear with the following two examples. With debug_zval_dump():

<?php
$a = array(1, 2, 3);
$b =& $a;
$c =& $a[2];

debug_zval_dump($a);
?>

Which outputs (after a little formatting):

array(3) refcount(1){
        [0]=> long(1) refcount(2)
        [1]=> long(2) refcount(2)
        [2]=> &long(3) refcount(3)
}

And with xdebug_debug_zval():

<?php
$a = array(1, 2, 3);
$b =& $a;
$c =& $a[2];

xdebug_debug_zval('a');
?>

Which outputs (after a little formatting):

a: (refcount=2, is_ref=1)=array (
        0 => (refcount=1, is_ref=0)=1,
        1 => (refcount=1, is_ref=0)=2,
        2 => (refcount=2, is_ref=1)=3
)

In the debug_zval_dump() example, the refcounts for the array elements are all one too high, and the refcount for the array itself is one too low. The array is also not marked as reference.

However, before Xdebug 2.3, the xdebug_debug_zval() function would only accept a variable name, but not any array subscripts or property deferences. Meaning that you couldn't really dump a sub array. Xdebug 2.3 adds support for dereferencing properties and array elements by reusing the variable name parser of the remote debugging. Hence, you can now do the following:

<?php
$a = array(1, 2, 3);
$b =& $a;
$c =& $a[2];

xdebug_debug_zval('a[2]');
?>

Which outputs:

a[2]: (refcount=2, is_ref=1)=3

Or:

<?php
$a = new StdClass;
$a->prop = [3.14, 2.72];

xdebug_debug_zval('a->prop');
xdebug_debug_zval('a->prop[1]');
?>

Which outputs:

a->prop: (refcount=1, is_ref=0)=array (
        0 => (refcount=1, is_ref=0)=3.14,
        1 => (refcount=1, is_ref=0)=2.72
)
a->prop[1]: (refcount=1, is_ref=0)=2.72


Other parts in this series:

Shortlink

This article has a short URL available: http://drck.me/debugzval23-bni

Comments

No comments yet

Life Line