--- deliantra/server/lib/cf.pm 2007/10/08 18:19:39 1.381 +++ deliantra/server/lib/cf.pm 2008/01/14 11:41:48 1.409 @@ -6,29 +6,30 @@ use Symbol; use List::Util; use Socket; -use Storable; -use Event; +use EV 1.86; use Opcode; use Safe; use Safe::Hole; +use Storable (); -use Coro 4.1 (); +use Coro 4.32 (); use Coro::State; use Coro::Handle; -use Coro::Event; +use Coro::EV; use Coro::Timer; use Coro::Signal; use Coro::Semaphore; use Coro::AIO; +use Coro::BDB; use Coro::Storable; use Coro::Util (); -use JSON::XS (); +use JSON::XS 2.01 (); use BDB (); use Data::Dumper; use Digest::MD5; use Fcntl; -use YAML::Syck (); +use YAML (); use IO::AIO 2.51 (); use Time::HiRes; use Compress::LZF; @@ -40,11 +41,6 @@ Coro::State::cctx_stacksize 256000; # 1-2MB stack, for deep recursions in maze generator Compress::LZF::sfreeze_cr { }; # prime Compress::LZF so it does not use require later -$Event::Eval = 1; # no idea why this is required, but it is - -# work around bug in YAML::Syck - bad news for perl6, will it be as broken wrt. unicode? -$YAML::Syck::ImplicitUnicode = 1; - $Coro::main->prio (Coro::PRIO_MAX); # run main coroutine ("the server") with very high priority sub WF_AUTOCANCEL () { 1 } # automatically cancel this watcher on reload @@ -72,13 +68,13 @@ our $PLAYERDIR = "$LOCALDIR/" . playerdir; our $RANDOMDIR = "$LOCALDIR/random"; our $BDBDIR = "$LOCALDIR/db"; +our %RESOURCE; our $TICK = MAX_TIME * 1e-6; # this is a CONSTANT(!) our $TICK_WATCHER; our $AIO_POLL_WATCHER; our $NEXT_RUNTIME_WRITE; # when should the runtime file be written our $NEXT_TICK; -our $NOW; our $USE_FSYNC = 1; # use fsync to write maps - default off our $BDB_POLL_WATCHER; @@ -91,6 +87,7 @@ our $UPTIME; $UPTIME ||= time; our $RUNTIME; +our $NOW; our (%PLAYER, %PLAYER_LOADING); # all users our (%MAP, %MAP_LOADING ); # all maps @@ -164,7 +161,7 @@ =item %cf::CFG -Configuration for the server, loaded from C, or +Configuration for the server, loaded from C, or from wherever your confdir points to. =item cf::wait_for_tick, cf::wait_for_tick_begin @@ -196,6 +193,11 @@ }; } +$Coro::State::DIEHOOK = sub { + warn Carp::longmess $_[0]; + Coro::terminate; +}; + @safe::cf::global::ISA = @cf::global::ISA = 'cf::attachable'; @safe::cf::object::ISA = @cf::object::ISA = 'cf::attachable'; @safe::cf::player::ISA = @cf::player::ISA = 'cf::attachable'; @@ -217,7 +219,7 @@ @{"safe::$pkg\::wrap::ISA"} = @{"$pkg\::wrap::ISA"} = $pkg; } -$Event::DIED = sub { +$EV::DIED = sub { warn "error in event callback: @_"; }; @@ -250,11 +252,11 @@ } || "[unable to dump $_[0]: '$@']"; } -=item $ref = cf::from_json $json +=item $ref = cf::decode_json $json Converts a JSON string into the corresponding perl data structure. -=item $json = cf::to_json $ref +=item $json = cf::encode_json $ref Converts a perl data structure into its JSON representation. @@ -262,8 +264,8 @@ our $json_coder = JSON::XS->new->utf8->max_size (1e6); # accept ~1mb max -sub to_json ($) { $json_coder->encode ($_[0]) } -sub from_json ($) { $json_coder->decode ($_[0]) } +sub encode_json($) { $json_coder->encode ($_[0]) } +sub decode_json($) { $json_coder->decode ($_[0]) } =item cf::lock_wait $string @@ -338,6 +340,21 @@ $guard } +=item cf::periodic $interval, $cb + +Like EV::periodic, but randomly selects a starting point so that the actions +get spread over timer. + +=cut + +sub periodic($$) { + my ($interval, $cb) = @_; + + my $start = rand List::Util::min 180, $interval; + + EV::periodic $start, $interval, 0, $cb +} + =item cf::get_slot $time[, $priority[, $name]] Allocate $time seconds of blocking CPU time at priority C<$priority>: @@ -408,8 +425,8 @@ =item cf::sync_job { BLOCK } -The design of Crossfire TRT requires that the main coroutine ($Coro::main) -is always able to handle events or runnable, as Crossfire TRT is only +The design of Deliantra requires that the main coroutine ($Coro::main) +is always able to handle events or runnable, as Deliantra is only partly reentrant. Thus "blocking" it by e.g. waiting for I/O is not acceptable. @@ -424,12 +441,12 @@ my ($job) = @_; if ($Coro::current == $Coro::main) { - my $time = Event::time; + my $time = EV::time; # this is the main coro, too bad, we have to block # till the operation succeeds, freezing the server :/ - LOG llevError | logBacktrace, Carp::longmess "sync job";#d# + LOG llevError, Carp::longmess "sync job";#d# # TODO: use suspend/resume instead # (but this is cancel-safe) @@ -446,10 +463,14 @@ })->prio (Coro::PRIO_MAX); while ($busy) { - Coro::cede or Event::one_event; + if (Coro::nready) { + Coro::cede_notself; + } else { + EV::loop EV::LOOP_ONESHOT; + } } - $time = Event::time - $time; + $time = EV::time - $time; LOG llevError | logBacktrace, Carp::longmess "long sync job" if $time > $TICK * 0.5 && $TICK_WATCHER->is_active; @@ -489,7 +510,7 @@ Executes the given code block with the given arguments in a seperate process, returning the results. Everything must be serialisable with Coro::Storable. May, of course, block. Note that the executed sub may -never block itself or use any form of Event handling. +never block itself or use any form of event handling. =cut @@ -660,7 +681,7 @@ In the following description, CLASS can be any of C, C C, C or C (i.e. the attachable objects in -Crossfire TRT). +Deliantra). =over 4 @@ -952,7 +973,7 @@ 0 } -=item $bool = cf::global::invoke (EVENT_CLASS_XXX, ...) +=item $bool = cf::global->invoke (EVENT_CLASS_XXX, ...) =item $bool = $attachable->invoke (EVENT_CLASS_XXX, ...) @@ -968,16 +989,47 @@ ############################################################################# # object support -# +sub _object_equal($$); +sub _object_equal($$) { + my ($a, $b) = @_; + + return 0 unless (ref $a) eq (ref $b); + + if ("HASH" eq ref $a) { + my @ka = keys %$a; + my @kb = keys %$b; + + return 0 if @ka != @kb; + + for (0 .. $#ka) { + return 0 unless $ka[$_] eq $kb[$_]; + return 0 unless _object_equal $a->{$ka[$_]}, $b->{$kb[$_]}; + } + + } elsif ("ARRAY" eq ref $a) { + + return 0 if @$a != @$b; + + for (0 .. $#$a) { + return 0 unless _object_equal $a->[$_], $b->[$_]; + } + + } elsif ($a ne $b) { + return 0; + } + + 1 +} + +our $SLOW_MERGES;#d# sub _can_merge { my ($ob1, $ob2) = @_; - local $Storable::canonical = 1; - my $fob1 = Storable::freeze $ob1; - my $fob2 = Storable::freeze $ob2; + ++$SLOW_MERGES;#d# - $fob1 eq $fob2 + # we do the slow way here + return _object_equal $ob1, $ob2 } sub reattach { @@ -1009,7 +1061,7 @@ on_instantiate => sub { my ($obj, $data) = @_; - $data = from_json $data; + $data = decode_json $data; for (@$data) { my ($name, $args) = @$_; @@ -1089,8 +1141,7 @@ (aio_load "$filename.pst", $av) >= 0 or return; - my $st = eval { Coro::Storable::thaw $av } - || eval { my $guard = Coro::Storable::guard; Storable::thaw $av }; #d# compatibility, remove + my $st = eval { Coro::Storable::thaw $av }; $av = $st->{objs}; } @@ -1516,46 +1567,88 @@ =cut +use re 'eval'; + +my $group; +my $interior; $interior = qr{ + # match a pod interior sequence sans C<< >> + (?: + \ (.*?)\ (?{ $group = $^N }) + | < (??{$interior}) > + ) +}x; + sub expand_cfpod { - ((my $self), (local $_)) = @_; + my ($self, $pod) = @_; + + my $xml; + + while () { + if ($pod =~ /\G( (?: [^BCGHITU]+ | .(?!<) )+ )/xgcs) { + $group = $1; + + $group =~ s/&/&/g; + $group =~ s/]*) (?{ $group = $^N }) + | < $interior > + ) + > + %gcsx + ) { + my ($code, $data) = ($1, $group); + + if ($code eq "B") { + $xml .= "" . expand_cfpod ($self, $data) . ""; + } elsif ($code eq "I") { + $xml .= "" . expand_cfpod ($self, $data) . ""; + } elsif ($code eq "U") { + $xml .= "" . expand_cfpod ($self, $data) . ""; + } elsif ($code eq "C") { + $xml .= "" . expand_cfpod ($self, $data) . ""; + } elsif ($code eq "T") { + $xml .= "" . expand_cfpod ($self, $data) . ""; + } elsif ($code eq "G") { + my ($male, $female) = split /\|/, $data; + $data = $self->gender ? $female : $male; + $xml .= expand_cfpod ($self, $data); + } elsif ($code eq "H") { + $xml .= ("[" . expand_cfpod ($self, $data) . " (Use hintmode to suppress hints)]", + "[Hint suppressed, see hintmode]", + "") + [$self->{hintmode}]; + } else { + $xml .= "error processing '$code($data)' directive"; + } + } else { + if ($pod =~ /\G(.+)/) { + warn "parse error while expanding $pod (at $1)"; + } + last; + } + } - # escape & and < - s/&/&/g; - s/(?, I<>, U<> etc. - s/B<([^\>]*)>/$1<\/b>/ - || s/I<([^\>]*)>/$1<\/i>/ - || s/U<([^\>]*)>/$1<\/u>/ - || s/T<([^\>]*)>/$1<\/b><\/big>/ - # replace G tags - || s{G<([^>|]*)\|([^>]*)>}{ - $self->gender ? $2 : $1 - }ge - # replace H - || s{H<([^\>]*)>} - { - ("[$1 (Use hintmode to suppress hints)]", - "[Hint suppressed, see hintmode]", - "") - [$self->{hintmode}] - }ge; - - # create single paragraphs (very hackish) - s/(?<=\S)\n(?=\w)/ /g; - - # compress some whitespace - s/\s+\n/\n/g; # ws line-ends - s/\n\n+/\n/g; # double lines - s/^\n+//; # beginning lines - s/\n+$//; # ending lines + for ($xml) { + # create single paragraphs (very hackish) + s/(?<=\S)\n(?=\w)/ /g; - $_ + # compress some whitespace + s/\s+\n/\n/g; # ws line-ends + s/\n\n+/\n/g; # double lines + s/^\n+//; # beginning lines + s/\n+$//; # ending lines + } + + $xml } +no re 'eval'; + sub hintmode { $_[0]{hintmode} = $_[1] if @_ > 1; $_[0]{hintmode} @@ -2551,7 +2644,7 @@ $rmp->{random_seed} ||= $exit->random_seed; - my $data = cf::to_json $rmp; + my $data = cf::encode_json $rmp; my $md5 = Digest::MD5::md5_hex $data; my $meta = "$RANDOMDIR/$md5.meta"; @@ -2634,6 +2727,7 @@ =cut +# non-persistent channels (usually the info channel) our %CHANNEL = ( "c/identify" => { id => "infobox", @@ -2647,12 +2741,42 @@ reply => undef, tooltip => "Signs and other items you examined", }, + "c/book" => { + id => "infobox", + title => "Book", + reply => undef, + tooltip => "The contents of a note or book", + }, "c/lookat" => { id => "infobox", title => "Look", reply => undef, tooltip => "What you saw there", }, + "c/who" => { + id => "infobox", + title => "Players", + reply => undef, + tooltip => "Shows players who are currently online", + }, + "c/body" => { + id => "infobox", + title => "Body Parts", + reply => undef, + tooltip => "Shows which body parts you posess and are available", + }, + "c/uptime" => { + id => "infobox", + title => "Uptime", + reply => undef, + tooltip => "How long the server has been running since last restart", + }, + "c/mapinfo" => { + id => "infobox", + title => "Map Info", + reply => undef, + tooltip => "Information related to the maps", + }, ); sub cf::client::send_msg { @@ -2898,7 +3022,7 @@ The following functions and methods are available within a safe environment: cf::object - contr pay_amount pay_player map x y force_find force_add + contr pay_amount pay_player map x y force_find force_add destroy insert remove name archname title slaying race decrease_ob_nr cf::object::player @@ -2915,7 +3039,7 @@ for ( ["cf::object" => qw(contr pay_amount pay_player map force_find force_add x y insert remove inv name archname title slaying race - decrease_ob_nr)], + decrease_ob_nr destroy)], ["cf::object::player" => qw(player)], ["cf::player" => qw(peaceful)], ["cf::map" => qw(trigger)], @@ -3030,6 +3154,7 @@ while (my ($face, $info) = each %$faces) { my $idx = (cf::face::find $face) || cf::face::alloc $face; + cf::face::set_visibility $idx, $info->{visibility}; cf::face::set_magicmap $idx, $info->{magicmap}; cf::face::set_data $idx, 0, $info->{data32}, Digest::MD5::md5 $info->{data32}; @@ -3040,8 +3165,10 @@ while (my ($face, $info) = each %$faces) { next unless $info->{smooth}; + my $idx = cf::face::find $face or next; + if (my $smooth = cf::face::find $info->{smooth}) { cf::face::set_smooth $idx, $smooth; cf::face::set_smoothlevel $idx, $info->{smoothlevel}; @@ -3069,52 +3196,58 @@ # that gcfclient doesn't grok a >10000 face index. my $res = $facedata->{resource}; - my $soundconf = delete $res->{"res/sound.conf"}; - while (my ($name, $info) = each %$res) { - my $idx = (cf::face::find $name) || cf::face::alloc $name; - my $data; - - if ($info->{type} & 1) { - # prepend meta info + if (defined $info->{type}) { + my $idx = (cf::face::find $name) || cf::face::alloc $name; + my $data; + + if ($info->{type} & 1) { + # prepend meta info + + my $meta = $enc->encode ({ + name => $name, + %{ $info->{meta} || {} }, + }); - my $meta = $enc->encode ({ - name => $name, - %{ $info->{meta} || {} }, - }); + $data = pack "(w/a*)*", $meta, $info->{data}; + } else { + $data = $info->{data}; + } - $data = pack "(w/a*)*", $meta, $info->{data}; + cf::face::set_data $idx, 0, $data, Digest::MD5::md5 $data; + cf::face::set_type $idx, $info->{type}; } else { - $data = $info->{data}; + $RESOURCE{$name} = $info; } - cf::face::set_data $idx, 0, $data, Digest::MD5::md5 $data; - cf::face::set_type $idx, $info->{type}; - cf::cede_to_tick; } + } - if ($soundconf) { - $soundconf = $enc->decode (delete $soundconf->{data}); + cf::global->invoke (EVENT_GLOBAL_RESOURCE_UPDATE); - for (0 .. SOUND_CAST_SPELL_0 - 1) { - my $sound = $soundconf->{compat}[$_] - or next; + 1 +} - my $face = cf::face::find "sound/$sound->[1]"; - cf::sound::set $sound->[0] => $face; - cf::sound::old_sound_index $_, $face; # gcfclient-compat - } +cf::global->attach (on_resource_update => sub { + if (my $soundconf = $RESOURCE{"res/sound.conf"}) { + $soundconf = JSON::XS->new->utf8->relaxed->decode ($soundconf->{data}); - while (my ($k, $v) = each %{$soundconf->{event}}) { - my $face = cf::face::find "sound/$v"; - cf::sound::set $k => $face; - } + for (0 .. SOUND_CAST_SPELL_0 - 1) { + my $sound = $soundconf->{compat}[$_] + or next; + + my $face = cf::face::find "sound/$sound->[1]"; + cf::sound::set $sound->[0] => $face; + cf::sound::old_sound_index $_, $face; # gcfclient-compat } - } - 1 -} + while (my ($k, $v) = each %{$soundconf->{event}}) { + my $face = cf::face::find "sound/$v"; + cf::sound::set $k => $face; + } + } +}); register_exticmd fx_want => sub { my ($ns, $want) = @_; @@ -3179,7 +3312,7 @@ or return; local $/; - *CFG = YAML::Syck::Load <$fh>; + *CFG = YAML::Load <$fh>; $EMERGENCY_POSITION = $CFG{emergency_position} || ["/world/world_105_115", 5, 37]; @@ -3201,7 +3334,7 @@ Carp::cluck "FATAL: Coro::idle was called, major BUG, use cf::sync_job!\n";#d# (async { $Coro::current->{desc} = "IDLE BUG HANDLER"; - Event::one_event; + EV::loop EV::LOOP_ONESHOT; })->prio (Coro::PRIO_MAX); }; @@ -3210,7 +3343,8 @@ load_extensions; $TICK_WATCHER->start; - Event::loop; + $Coro::current->prio (Coro::PRIO_MAX); # give the main loop max. priority + EV::loop; } ############################################################################# @@ -3218,16 +3352,11 @@ # install some emergency cleanup handlers BEGIN { + our %SIGWATCHER = (); for my $signal (qw(INT HUP TERM)) { - Event->signal ( - reentrant => 0, - data => WF_AUTOCANCEL, - signal => $signal, - prio => 0, - cb => sub { - cf::cleanup "SIG$signal"; - }, - ); + $SIGWATCHER{$signal} = EV::signal $signal, sub { + cf::cleanup "SIG$signal"; + }; } } @@ -3282,7 +3411,7 @@ for my $login (keys %cf::PLAYER) { my $pl = $cf::PLAYER{$login} or next; $pl->valid or next; - delete $pl->{unclean_save}; + delete $pl->{unclean_save}; # not strictly necessary, but cannot hurt $pl->save; } warn "end emergency player save\n"; @@ -3331,16 +3460,11 @@ # if anything goes wrong in here, we should simply crash as we already saved - warn "cancelling all WF_AUTOCANCEL watchers"; - for (Event::all_watchers) { - $_->cancel if $_->data & WF_AUTOCANCEL; - } - warn "flushing outstanding aio requests"; for (;;) { BDB::flush; IO::AIO::flush; - Coro::cede; + Coro::cede_notself; last unless IO::AIO::nreqs || BDB::nreqs; warn "iterate..."; } @@ -3439,15 +3563,10 @@ # doing reload synchronously and two reloads happen back-to-back, # coro crashes during coro_state_free->destroy here. - $RELOAD_WATCHER ||= Event->timer ( - reentrant => 0, - after => 0, - data => WF_AUTOCANCEL, - cb => sub { - do_reload_perl; - undef $RELOAD_WATCHER; - }, - ); + $RELOAD_WATCHER ||= EV::timer 0, 0, sub { + do_reload_perl; + undef $RELOAD_WATCHER; + }; } register_command "reload" => sub { @@ -3487,83 +3606,49 @@ $signal->wait; } -$TICK_WATCHER = Event->timer ( - reentrant => 0, - parked => 1, - prio => 0, - at => $NEXT_TICK || $TICK, - data => WF_AUTOCANCEL, - cb => sub { - if ($Coro::current != $Coro::main) { - Carp::cluck "major BUG: server tick called outside of main coro, skipping it" - unless ++$bug_warning > 10; - return; - } - - $NOW = $tick_start = Event::time; - - cf::server_tick; # one server iteration - - $RUNTIME += $TICK; - $NEXT_TICK += $TICK; - - if ($NOW >= $NEXT_RUNTIME_WRITE) { - $NEXT_RUNTIME_WRITE = $NOW + 10; - Coro::async_pool { - $Coro::current->{desc} = "runtime saver"; - write_runtime - or warn "ERROR: unable to write runtime file: $!"; - }; - } +$TICK_WATCHER = EV::periodic_ns 0, $TICK, 0, sub { + if ($Coro::current != $Coro::main) { + Carp::cluck "major BUG: server tick called outside of main coro, skipping it" + unless ++$bug_warning > 10; + return; + } - if (my $sig = shift @WAIT_FOR_TICK_BEGIN) { - $sig->send; - } - while (my $sig = shift @WAIT_FOR_TICK) { - $sig->send; - } + $NOW = $tick_start = EV::now; - $NOW = Event::time; + cf::server_tick; # one server iteration - # if we are delayed by four ticks or more, skip them all - $NEXT_TICK = $NOW if $NOW >= $NEXT_TICK + $TICK * 4; + $RUNTIME += $TICK; + $NEXT_TICK = $_[0]->at; - $TICK_WATCHER->at ($NEXT_TICK); - $TICK_WATCHER->start; + if ($NOW >= $NEXT_RUNTIME_WRITE) { + $NEXT_RUNTIME_WRITE = List::Util::max $NEXT_RUNTIME_WRITE + 10, $NOW + 5.; + Coro::async_pool { + $Coro::current->{desc} = "runtime saver"; + write_runtime + or warn "ERROR: unable to write runtime file: $!"; + }; + } - $LOAD = ($NOW - $tick_start) / $TICK; - $LOADAVG = $LOADAVG * 0.75 + $LOAD * 0.25; + if (my $sig = shift @WAIT_FOR_TICK_BEGIN) { + $sig->send; + } + while (my $sig = shift @WAIT_FOR_TICK) { + $sig->send; + } - _post_tick; - }, -); + $LOAD = ($NOW - $tick_start) / $TICK; + $LOADAVG = $LOADAVG * 0.75 + $LOAD * 0.25; + + _post_tick; +}; +$TICK_WATCHER->priority (EV::MAXPRI); { - BDB::min_parallel 8; - BDB::max_poll_time $TICK * 0.1; - $BDB_POLL_WATCHER = Event->io ( - reentrant => 0, - fd => BDB::poll_fileno, - poll => 'r', - prio => 0, - data => WF_AUTOCANCEL, - cb => \&BDB::poll_cb, - ); + # configure BDB - BDB::set_sync_prepare { - my $status; - my $current = $Coro::current; - ( - sub { - $status = $!; - $current->ready; undef $current; - }, - sub { - Coro::schedule while defined $current; - $! = $status; - }, - ) - }; + BDB::min_parallel 8; + BDB::max_poll_reqs $TICK * 0.1; + $Coro::BDB::WATCHER->priority (1); unless ($DB_ENV) { $DB_ENV = BDB::db_env_create; @@ -3588,51 +3673,23 @@ }; } - $BDB_DEADLOCK_WATCHER = Event->timer ( - after => 3, - interval => 1, - hard => 1, - prio => 0, - data => WF_AUTOCANCEL, - cb => sub { - BDB::db_env_lock_detect $DB_ENV, 0, BDB::LOCK_DEFAULT, 0, sub { }; - }, - ); - $BDB_CHECKPOINT_WATCHER = Event->timer ( - after => 11, - interval => 60, - hard => 1, - prio => 0, - data => WF_AUTOCANCEL, - cb => sub { - BDB::db_env_txn_checkpoint $DB_ENV, 0, 0, 0, sub { }; - }, - ); - $BDB_TRICKLE_WATCHER = Event->timer ( - after => 5, - interval => 10, - hard => 1, - prio => 0, - data => WF_AUTOCANCEL, - cb => sub { - BDB::db_env_memp_trickle $DB_ENV, 20, 0, sub { }; - }, - ); + $BDB_DEADLOCK_WATCHER = EV::periodic 0, 3, 0, sub { + BDB::db_env_lock_detect $DB_ENV, 0, BDB::LOCK_DEFAULT, 0, sub { }; + }; + $BDB_CHECKPOINT_WATCHER = EV::periodic 0, 60, 0, sub { + BDB::db_env_txn_checkpoint $DB_ENV, 0, 0, 0, sub { }; + }; + $BDB_TRICKLE_WATCHER = EV::periodic 0, 10, 0, sub { + BDB::db_env_memp_trickle $DB_ENV, 20, 0, sub { }; + }; } { - IO::AIO::min_parallel 8; + # configure IO::AIO - undef $Coro::AIO::WATCHER; + IO::AIO::min_parallel 8; IO::AIO::max_poll_time $TICK * 0.1; - $AIO_POLL_WATCHER = Event->io ( - reentrant => 0, - data => WF_AUTOCANCEL, - fd => IO::AIO::poll_fileno, - poll => 'r', - prio => 0, - cb => \&IO::AIO::poll_cb, - ); + $Coro::AIO::WATCHER->priority (1); } my $_log_backtrace;