| Filename | /home/hejohns/perl5/lib/perl5/IPC/Run/Debug.pm |
| Statements | Executed 15 statements in 278µs |
| Calls | P | F | Exclusive Time |
Inclusive Time |
Subroutine |
|---|---|---|---|---|---|
| 1 | 1 | 1 | 12µs | 12µs | IPC::Run::Debug::BEGIN@74 |
| 1 | 1 | 1 | 7µs | 8µs | IPC::Run::Debug::BEGIN@69 |
| 1 | 1 | 1 | 4µs | 11µs | IPC::Run::Debug::BEGIN@71 |
| 1 | 1 | 1 | 3µs | 13µs | IPC::Run::Debug::BEGIN@70 |
| 1 | 1 | 1 | 3µs | 30µs | IPC::Run::Debug::BEGIN@72 |
| Line | State ments |
Time on line |
Calls | Time in subs |
Code |
|---|---|---|---|---|---|
| 1 | package IPC::Run::Debug; | ||||
| 2 | |||||
| 3 | =pod | ||||
| 4 | |||||
| 5 | =head1 NAME | ||||
| 6 | |||||
| 7 | IPC::Run::Debug - debugging routines for IPC::Run | ||||
| 8 | |||||
| 9 | =head1 SYNOPSIS | ||||
| 10 | |||||
| 11 | ## | ||||
| 12 | ## Environment variable usage | ||||
| 13 | ## | ||||
| 14 | ## To force debugging off and shave a bit of CPU and memory | ||||
| 15 | ## by compile-time optimizing away all debugging code in IPC::Run | ||||
| 16 | ## (debug => ...) options to IPC::Run will be ignored. | ||||
| 17 | export IPCRUNDEBUG=none | ||||
| 18 | |||||
| 19 | ## To force debugging on (levels are from 0..10) | ||||
| 20 | export IPCRUNDEBUG=basic | ||||
| 21 | |||||
| 22 | ## Leave unset or set to "" to compile in debugging support and | ||||
| 23 | ## allow runtime control of it using the debug option. | ||||
| 24 | |||||
| 25 | =head1 DESCRIPTION | ||||
| 26 | |||||
| 27 | Controls IPC::Run debugging. Debugging levels are now set by using words, | ||||
| 28 | but the numbers shown are still supported for backwards compatibility: | ||||
| 29 | |||||
| 30 | 0 none disabled (special, see below) | ||||
| 31 | 1 basic what's running | ||||
| 32 | 2 data what's being sent/received | ||||
| 33 | 3 details what's going on in more detail | ||||
| 34 | 4 gory way too much detail for most uses | ||||
| 35 | 10 all use this when submitting bug reports | ||||
| 36 | noopts optimizations forbidden due to inherited STDIN | ||||
| 37 | |||||
| 38 | The C<none> level is special when the environment variable IPCRUNDEBUG | ||||
| 39 | is set to this the first time IPC::Run::Debug is loaded: it prevents | ||||
| 40 | the debugging code from being compiled in to the remaining IPC::Run modules, | ||||
| 41 | saving a bit of cpu. | ||||
| 42 | |||||
| 43 | To do this in a script, here's a way that allows it to be overridden: | ||||
| 44 | |||||
| 45 | BEGIN { | ||||
| 46 | unless ( defined $ENV{IPCRUNDEBUG} ) { | ||||
| 47 | eval 'local $ENV{IPCRUNDEBUG} = "none"; require IPC::Run::Debug"' | ||||
| 48 | or die $@; | ||||
| 49 | } | ||||
| 50 | } | ||||
| 51 | |||||
| 52 | This should force IPC::Run to not be debuggable unless somebody sets | ||||
| 53 | the IPCRUNDEBUG flag; modify this formula to grep @ARGV if need be: | ||||
| 54 | |||||
| 55 | BEGIN { | ||||
| 56 | unless ( grep /^--debug/, @ARGV ) { | ||||
| 57 | eval 'local $ENV{IPCRUNDEBUG} = "none"; require IPC::Run::Debug"' | ||||
| 58 | or die $@; | ||||
| 59 | } | ||||
| 60 | |||||
| 61 | Both of those are untested. | ||||
| 62 | |||||
| 63 | =cut | ||||
| 64 | |||||
| 65 | ## We use @EXPORT for the end user's convenience: there's only one function | ||||
| 66 | ## exported, it's homonymous with the module, it's an unusual name, and | ||||
| 67 | ## it can be suppressed by "use IPC::Run ();". | ||||
| 68 | |||||
| 69 | 2 | 18µs | 2 | 9µs | # spent 8µs (7+1) within IPC::Run::Debug::BEGIN@69 which was called:
# once (7µs+1µs) by IPC::Run::BEGIN@1052 at line 69 # spent 8µs making 1 call to IPC::Run::Debug::BEGIN@69
# spent 1µs making 1 call to strict::import |
| 70 | 2 | 11µs | 2 | 23µs | # spent 13µs (3+10) within IPC::Run::Debug::BEGIN@70 which was called:
# once (3µs+10µs) by IPC::Run::BEGIN@1052 at line 70 # spent 13µs making 1 call to IPC::Run::Debug::BEGIN@70
# spent 10µs making 1 call to warnings::import |
| 71 | 2 | 15µs | 2 | 19µs | # spent 11µs (4+8) within IPC::Run::Debug::BEGIN@71 which was called:
# once (4µs+8µs) by IPC::Run::BEGIN@1052 at line 71 # spent 11µs making 1 call to IPC::Run::Debug::BEGIN@71
# spent 8µs making 1 call to Exporter::import |
| 72 | 2 | 54µs | 2 | 58µs | # spent 30µs (3+28) within IPC::Run::Debug::BEGIN@72 which was called:
# once (3µs+28µs) by IPC::Run::BEGIN@1052 at line 72 # spent 30µs making 1 call to IPC::Run::Debug::BEGIN@72
# spent 28µs making 1 call to vars::import |
| 73 | |||||
| 74 | # spent 12µs within IPC::Run::Debug::BEGIN@74 which was called:
# once (12µs+0s) by IPC::Run::BEGIN@1052 at line 97 | ||||
| 75 | 1 | 300ns | $VERSION = '20220807.0'; | ||
| 76 | 1 | 5µs | @ISA = qw( Exporter ); | ||
| 77 | 1 | 3µs | @EXPORT = qw( | ||
| 78 | _debug | ||||
| 79 | _debug_desc_fd | ||||
| 80 | _debugging | ||||
| 81 | _debugging_data | ||||
| 82 | _debugging_details | ||||
| 83 | _debugging_gory_details | ||||
| 84 | _debugging_not_optimized | ||||
| 85 | _set_child_debug_name | ||||
| 86 | ); | ||||
| 87 | |||||
| 88 | 1 | 400ns | @EXPORT_OK = qw( | ||
| 89 | _debug_init | ||||
| 90 | _debugging_level | ||||
| 91 | _map_fds | ||||
| 92 | ); | ||||
| 93 | 1 | 3µs | %EXPORT_TAGS = ( | ||
| 94 | default => \@EXPORT, | ||||
| 95 | all => [ @EXPORT, @EXPORT_OK ], | ||||
| 96 | ); | ||||
| 97 | 1 | 120µs | 1 | 12µs | } # spent 12µs making 1 call to IPC::Run::Debug::BEGIN@74 |
| 98 | |||||
| 99 | my $disable_debugging = defined $ENV{IPCRUNDEBUG} | ||||
| 100 | && ( !$ENV{IPCRUNDEBUG} | ||||
| 101 | 1 | 600ns | || lc $ENV{IPCRUNDEBUG} eq "none" ); | ||
| 102 | |||||
| 103 | 1 | 48µs | eval( $disable_debugging ? <<'STUBS' : <<'SUBS' ) or die $@; # spent 108s executing statements in string eval # includes 91.2s spent executing 25174040 calls to 14 subs defined therein. | ||
| 104 | sub _map_fds() { "" } | ||||
| 105 | sub _debug {} | ||||
| 106 | sub _debug_desc_fd {} | ||||
| 107 | sub _debug_init {} | ||||
| 108 | sub _set_child_debug_name {} | ||||
| 109 | sub _debugging() { 0 } | ||||
| 110 | sub _debugging_level() { 0 } | ||||
| 111 | sub _debugging_data() { 0 } | ||||
| 112 | sub _debugging_details() { 0 } | ||||
| 113 | sub _debugging_gory_details() { 0 } | ||||
| 114 | sub _debugging_not_optimized() { 0 } | ||||
| 115 | |||||
| 116 | 1; | ||||
| 117 | STUBS | ||||
| 118 | |||||
| 119 | use POSIX (); | ||||
| 120 | |||||
| 121 | sub _map_fds { | ||||
| 122 | my $map = ''; | ||||
| 123 | my $digit = 0; | ||||
| 124 | my $in_use; | ||||
| 125 | my $dummy; | ||||
| 126 | for my $fd (0..63) { | ||||
| 127 | ## I'd like a quicker way (less user, cpu & especially sys and kernel | ||||
| 128 | ## calls) to detect open file descriptors. Let me know... | ||||
| 129 | ## Hmmm, could do a 0 length read and check for bad file descriptor... | ||||
| 130 | ## but that segfaults on Win32 | ||||
| 131 | my $test_fd = POSIX::dup( $fd ); | ||||
| 132 | $in_use = defined $test_fd; | ||||
| 133 | POSIX::close $test_fd if $in_use; | ||||
| 134 | $map .= $in_use ? $digit : '-'; | ||||
| 135 | $digit = 0 if ++$digit > 9; | ||||
| 136 | } | ||||
| 137 | warn "No fds open???" unless $map =~ /\d/; | ||||
| 138 | $map =~ s/(.{1,12})-*$/$1/; | ||||
| 139 | return $map; | ||||
| 140 | } | ||||
| 141 | |||||
| 142 | use vars qw( $parent_pid ); | ||||
| 143 | |||||
| 144 | $parent_pid = $$; | ||||
| 145 | |||||
| 146 | ## TODO: move debugging to its own module and make it compile-time | ||||
| 147 | ## optimizable. | ||||
| 148 | |||||
| 149 | ## Give kid process debugging nice names | ||||
| 150 | my $debug_name; | ||||
| 151 | |||||
| 152 | sub _set_child_debug_name { | ||||
| 153 | $debug_name = shift; | ||||
| 154 | } | ||||
| 155 | |||||
| 156 | ## There's a bit of hackery going on here. | ||||
| 157 | ## | ||||
| 158 | ## We want to have any code anywhere be able to emit | ||||
| 159 | ## debugging statements without knowing what harness the code is | ||||
| 160 | ## being called in/from, since we'd need to pass a harness around to | ||||
| 161 | ## everything. | ||||
| 162 | ## | ||||
| 163 | ## Thus, $cur_self was born. | ||||
| 164 | # | ||||
| 165 | my %debug_levels = ( | ||||
| 166 | none => 0, | ||||
| 167 | basic => 1, | ||||
| 168 | data => 2, | ||||
| 169 | details => 3, | ||||
| 170 | gore => 4, | ||||
| 171 | gory_details => 4, | ||||
| 172 | "gory details" => 4, | ||||
| 173 | gory => 4, | ||||
| 174 | gorydetails => 4, | ||||
| 175 | all => 10, | ||||
| 176 | notopt => 0, | ||||
| 177 | ); | ||||
| 178 | |||||
| 179 | my $warned; | ||||
| 180 | |||||
| 181 | sub _debugging_level() { | ||||
| 182 | my $level = 0; | ||||
| 183 | |||||
| 184 | $level = $IPC::Run::cur_self->{debug} || 0 | ||||
| 185 | if $IPC::Run::cur_self | ||||
| 186 | && ( $IPC::Run::cur_self->{debug} || 0 ) >= $level; | ||||
| 187 | |||||
| 188 | if ( defined $ENV{IPCRUNDEBUG} ) { | ||||
| 189 | my $v = $ENV{IPCRUNDEBUG}; | ||||
| 190 | $v = $debug_levels{lc $v} if $v =~ /[a-zA-Z]/; | ||||
| 191 | unless ( defined $v ) { | ||||
| 192 | $warned ||= warn "Unknown debug level $ENV{IPCRUNDEBUG}, assuming 'basic' (1)\n"; | ||||
| 193 | $v = 1; | ||||
| 194 | } | ||||
| 195 | $level = $v if $v > $level; | ||||
| 196 | } | ||||
| 197 | return $level; | ||||
| 198 | } | ||||
| 199 | |||||
| 200 | sub _debugging_atleast($) { | ||||
| 201 | my $min_level = shift || 1; | ||||
| 202 | |||||
| 203 | my $level = _debugging_level; | ||||
| 204 | |||||
| 205 | return $level >= $min_level ? $level : 0; | ||||
| 206 | } | ||||
| 207 | |||||
| 208 | sub _debugging() { _debugging_atleast 1 } | ||||
| 209 | sub _debugging_data() { _debugging_atleast 2 } | ||||
| 210 | sub _debugging_details() { _debugging_atleast 3 } | ||||
| 211 | sub _debugging_gory_details() { _debugging_atleast 4 } | ||||
| 212 | sub _debugging_not_optimized() { ( $ENV{IPCRUNDEBUG} || "" ) eq "notopt" } | ||||
| 213 | |||||
| 214 | sub _debug_init { | ||||
| 215 | ## This routine is called only in spawned children to fake out the | ||||
| 216 | ## debug routines so they'll emit debugging info. | ||||
| 217 | $IPC::Run::cur_self = {}; | ||||
| 218 | ( $parent_pid, | ||||
| 219 | $^T, | ||||
| 220 | $IPC::Run::cur_self->{debug}, | ||||
| 221 | $IPC::Run::cur_self->{DEBUG_FD}, | ||||
| 222 | $debug_name | ||||
| 223 | ) = @_; | ||||
| 224 | } | ||||
| 225 | |||||
| 226 | |||||
| 227 | sub _debug { | ||||
| 228 | # return unless _debugging || _debugging_not_optimized; | ||||
| 229 | |||||
| 230 | my $fd = defined &IPC::Run::_debug_fd | ||||
| 231 | ? IPC::Run::_debug_fd() | ||||
| 232 | : fileno STDERR; | ||||
| 233 | |||||
| 234 | my $s; | ||||
| 235 | my $debug_id; | ||||
| 236 | $debug_id = join( | ||||
| 237 | " ", | ||||
| 238 | join( | ||||
| 239 | "", | ||||
| 240 | defined $IPC::Run::cur_self && defined $IPC::Run::cur_self->{ID} | ||||
| 241 | ? "#$IPC::Run::cur_self->{ID}" | ||||
| 242 | : (), | ||||
| 243 | "($$)", | ||||
| 244 | ), | ||||
| 245 | defined $debug_name && length $debug_name ? $debug_name : (), | ||||
| 246 | ); | ||||
| 247 | my $prefix = join( | ||||
| 248 | "", | ||||
| 249 | "IPC::Run", | ||||
| 250 | sprintf( " %04d", time - $^T ), | ||||
| 251 | ( _debugging_details ? ( " ", _map_fds ) : () ), | ||||
| 252 | length $debug_id ? ( " [", $debug_id, "]" ) : (), | ||||
| 253 | ": ", | ||||
| 254 | ); | ||||
| 255 | |||||
| 256 | my $msg = join( '', map defined $_ ? $_ : "<undef>", @_ ); | ||||
| 257 | chomp $msg; | ||||
| 258 | $msg =~ s{^}{$prefix}gm; | ||||
| 259 | $msg .= "\n"; | ||||
| 260 | POSIX::write( $fd, $msg, length $msg ); | ||||
| 261 | } | ||||
| 262 | |||||
| 263 | |||||
| 264 | my @fd_descs = ( 'stdin', 'stdout', 'stderr' ); | ||||
| 265 | |||||
| 266 | sub _debug_desc_fd { | ||||
| 267 | return unless _debugging; | ||||
| 268 | my $text = shift; | ||||
| 269 | my $op = pop; | ||||
| 270 | my $kid = $_[0]; | ||||
| 271 | |||||
| 272 | Carp::carp join " ", caller(0), $text, $op if defined $op && UNIVERSAL::isa( $op, "IO::Pty" ); | ||||
| 273 | |||||
| 274 | _debug( | ||||
| 275 | $text, | ||||
| 276 | ' ', | ||||
| 277 | ( defined $op->{FD} | ||||
| 278 | ? $op->{FD} < 3 | ||||
| 279 | ? ( $fd_descs[$op->{FD}] ) | ||||
| 280 | : ( 'fd ', $op->{FD} ) | ||||
| 281 | : $op->{FD} | ||||
| 282 | ), | ||||
| 283 | ( defined $op->{KFD} | ||||
| 284 | ? ( | ||||
| 285 | ' (kid', | ||||
| 286 | ( defined $kid ? ( ' ', $kid->{NUM}, ) : () ), | ||||
| 287 | "'s ", | ||||
| 288 | ( $op->{KFD} < 3 | ||||
| 289 | ? $fd_descs[$op->{KFD}] | ||||
| 290 | : defined $kid | ||||
| 291 | && defined $kid->{DEBUG_FD} | ||||
| 292 | && $op->{KFD} == $kid->{DEBUG_FD} | ||||
| 293 | ? ( 'debug (', $op->{KFD}, ')' ) | ||||
| 294 | : ( 'fd ', $op->{KFD} ) | ||||
| 295 | ), | ||||
| 296 | ')', | ||||
| 297 | ) | ||||
| 298 | : () | ||||
| 299 | ), | ||||
| 300 | ); | ||||
| 301 | } | ||||
| 302 | |||||
| 303 | 1; | ||||
| 304 | |||||
| 305 | SUBS | ||||
| 306 | |||||
| 307 | =pod | ||||
| 308 | |||||
| 309 | =head1 AUTHOR | ||||
| 310 | |||||
| 311 | Barrie Slaymaker <barries@slaysys.com>, with numerous suggestions by p5p. | ||||
| 312 | |||||
| 313 | =cut |