[WWcvs] webwork2: added HiRes timing data to WeBWorK::Debug, removed

[Sam H. v. a. <we...@ma...>]

Log Message:
-----------
added HiRes timing data to WeBWorK::Debug, removed WeBWorK::Timing. all
existing calls to the WeBWorK::Timing methods now pass the same messages=20
to debug().

added an option to WeBWorK::Debug to allow only certain subroutines to
log debug messages, in addition to the existing option to bar certain
subroutines from doing so.

Modified Files:
--------------
    webwork2/lib:
        WeBWorK.pm
    webwork2/lib/WeBWorK:
        Constants.pm
        ContentGenerator.pm
        DB.pm
        Debug.pm
        URLPath.pm
    webwork2/lib/WeBWorK/ContentGenerator:
        GatewayQuiz.pm
        Grades.pm
        Hardcopy.pm
        Instructor.pm
        Problem.pm
        ProblemSet.pm
        ProblemSets.pm
    webwork2/lib/WeBWorK/ContentGenerator/Instructor:
        ProblemSetList.pm
        Scoring.pm
        SetsAssignedToUser.pm
        Stats.pm
        StudentProgress.pm
        UsersAssignedToSet.pm
    webwork2/lib/WeBWorK/DB/Schema:
        SQL.pm
        WW1Hash.pm

Removed Files:
-------------
    webwork2/lib/WeBWorK:
        Timing.pm

Revision Data
-------------
Index: DB.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/DB.pm,v
retrieving revision 1.65
retrieving revision 1.66
diff -Llib/WeBWorK/DB.pm -Llib/WeBWorK/DB.pm -u -r1.65 -r1.66
--- lib/WeBWorK/DB.pm
+++ lib/WeBWorK/DB.pm
@@ -140,7 +140,7 @@
 use warnings;
 use Carp;
 use Data::Dumper;
-use WeBWorK::Timing;
+use WeBWorK::Debug;
 use WeBWorK::Utils qw(runtime_use);
=20
 ########################################################################=
########
@@ -328,7 +328,7 @@
 	#=20
 	# yay!
 =09
-	$WeBWorK::timer->continue(__PACKAGE__ . "::hashDatabaseOK: about to get=
 orphaned UserSets") if defined $WeBWorK::timer;
+	debug(__PACKAGE__ . "::hashDatabaseOK: about to get orphaned UserSets")=
;
 =09
 	# ... so instead, we're going to do things manually
 =09
@@ -344,7 +344,7 @@
 			or return 0, @results, "Failed to connect to set_user database.";
 	=09
=20
-		# get PSVNs for global user (=EFN)
+		# get PSVNs for global user (=D4N)
 		# this reads from "login<>global_user"
 		my @globalUserPSVNs =3D $self->{set_user}->getPSVNsForUser($globalUser=
ID);
 		#warn "found ", scalar @globalUserPSVNs, " PSVNs for the global user.\=
n";
@@ -360,7 +360,7 @@
 		}
 	=09
=20
-		# get PSVNs for each setID (=EFN*M)
+		# get PSVNs for each setID (=D4N*M)
 		# this reads from "set<>$_"
 		my @okPSVNs =3D map { $self->{set_user}->getPSVNsForSet($_) } @globalU=
serSetIDs;
 		#warn "found ", scalar @okPSVNs, " PSVNs for sets assigned to the glob=
al user.\n";
@@ -407,7 +407,7 @@
 		}
 	}
 =09
-	$WeBWorK::timer->continue(__PACKAGE__ . "::hashDatabaseOK: done getting=
 orphaned UserSets") if defined $WeBWorK::timer;
+	debug(__PACKAGE__ . "::hashDatabaseOK: done getting orphaned UserSets")=
;
 =09
 	if (keys %orphanUserSets) {
 		foreach my $setID (keys %orphanUserSets) {
@@ -2033,25 +2033,25 @@
 	if (ref $self->{set_user} eq "WeBWorK::DB::Schema::WW1Hash"
 			and ref $self->{set} eq "WeBWorK::DB::Schema::GlobalTableEmulator") {
 		#warn __PACKAGE__.": using a terrible hack.\n";
-		$WeBWorK::timer->continue("DB: getsNoFilter start") if defined($WeBWor=
K::timer);
+		debug("DB: getsNoFilter start");
 		my @MergedSets =3D $self->{set_user}->getsNoFilter(@userSetIDs);
-		$WeBWorK::timer->continue("DB: getsNoFilter end") if defined($WeBWorK:=
:timer);
+		debug("DB: getsNoFilter end");
 		return @MergedSets;
 	}
 =09
-	$WeBWorK::timer->continue("DB: getUserSets start") if defined($WeBWorK:=
:timer);
+	debug("DB: getUserSets start");
 	my @UserSets =3D $self->getUserSets(@userSetIDs); # checked
 =09
-	$WeBWorK::timer->continue("DB: pull out set IDs start") if defined($WeB=
WorK::timer);
+	debug("DB: pull out set IDs start");
 	my @globalSetIDs =3D map { $_->[1] } @userSetIDs;
-	$WeBWorK::timer->continue("DB: getGlobalSets start") if defined($WeBWor=
K::timer);
+	debug("DB: getGlobalSets start");
 	my @GlobalSets =3D $self->getGlobalSets(@globalSetIDs); # checked
 =09
-	$WeBWorK::timer->continue("DB: calc common fields start") if defined($W=
eBWorK::timer);
+	debug("DB: calc common fields start");
 	my %globalSetFields =3D map { $_ =3D> 1 } $self->newGlobalSet->FIELDS;
 	my @commonFields =3D grep { exists $globalSetFields{$_} } $self->newUse=
rSet->FIELDS;
 =09
-	$WeBWorK::timer->continue("DB: merge start") if defined($WeBWorK::timer=
);
+	debug("DB: merge start");
 	for (my $i =3D 0; $i < @UserSets; $i++) {
 		my $UserSet =3D $UserSets[$i];
 		my $GlobalSet =3D $GlobalSets[$i];
@@ -2063,7 +2063,7 @@
 			$UserSet->$field($GlobalSet->$field);
 		}
 	}
-	$WeBWorK::timer->continue("DB: merge done!") if defined($WeBWorK::timer=
);
+	debug("DB: merge done!");
 =09
 	return @UserSets;
 }
@@ -2093,11 +2093,9 @@
     if (ref $self->{set_user} eq "WeBWorK::DB::Schema::WW1Hash"
 	and ref $self->{set} eq "WeBWorK::DB::Schema::GlobalTableEmulator") {
     #warn __PACKAGE__.": using a terrible hack.\n";
-#	$WeBWorK::timer->continue("DB: getsNoFilter start")=20
-#	    if defined($WeBWorK::timer);
+#	debug("DB: getsNoFilter start");
 #	my @MergedSets =3D $self->{set_user}->getsNoFilter(@versionedUserSetID=
s);
-#	$WeBWorK::timer->continue("DB: getsNoFilter end")=20
-#	    if defined($WeBWorK::timer);
+#	debug("DB: getsNoFilter end");
 #	return @MergedSets;
 	croak 'getMergedVersionedSets: using WW1Hash DB Schema!  Versioned ' .
 	    'sets are not supported in this context.';
@@ -2105,28 +2103,23 @@
=20
 # we merge the nonversioned ("template") user sets (user_id, set_id) and
 #    the global data into the versioned user sets=09
-    $WeBWorK::timer->continue("DB: getUserSets start (nonversioned)")=20
-	if defined($WeBWorK::timer);
+    debug("DB: getUserSets start (nonversioned)");
     my @TemplateUserSets =3D $self->getUserSets(@nonversionedUserSetIDs)=
;
-    $WeBWorK::timer->continue("DB: getUserSets start (versioned)")=20
-	if defined($WeBWorK::timer);
+    debug("DB: getUserSets start (versioned)");
 # these are the actual user sets that we want to use
     my @versionedUserSets =3D $self->getUserSets(@versionedUserSetIDs);
 =09
-    $WeBWorK::timer->continue("DB: pull out set IDs start")=20
-	if defined($WeBWorK::timer);
+    debug("DB: pull out set IDs start");
     my @globalSetIDs =3D map { $_->[1] } @userSetIDs;
-    $WeBWorK::timer->continue("DB: getGlobalSets start")=20
-	if defined($WeBWorK::timer);
+    debug("DB: getGlobalSets start");
     my @GlobalSets =3D $self->getGlobalSets(@globalSetIDs);
 =09
-    $WeBWorK::timer->continue("DB: calc common fields start")=20
-	if defined($WeBWorK::timer);
+    debug("DB: calc common fields start");
     my %globalSetFields =3D map { $_ =3D> 1 } $self->newGlobalSet->FIELD=
S;
     my @commonFields =3D=20
 	grep { exists $globalSetFields{$_} } $self->newUserSet->FIELDS;
 =09
-    $WeBWorK::timer->continue("DB: merge start") if defined($WeBWorK::ti=
mer);
+    debug("DB: merge start");
     for (my $i =3D 0; $i < @TemplateUserSets; $i++) {
 	next unless( defined $versionedUserSets[$i] and=20
 		     (defined $TemplateUserSets[$i] or
@@ -2143,7 +2136,7 @@
 		    $TemplateUserSets[$i]->$field ne '');
 	}
     }
-    $WeBWorK::timer->continue("DB: merge done!") if defined($WeBWorK::ti=
mer);
+    debug("DB: merge done!");
 =09
     return @versionedUserSets;
 }
@@ -2248,19 +2241,19 @@
 			       and defined $userProblemIDs[$i]->[2];
 	}
 =09
-	$WeBWorK::timer->continue("DB: getUserProblems start") if defined($WeBW=
orK::timer);
+	debug("DB: getUserProblems start");
 	my @UserProblems =3D $self->getUserProblems(@userProblemIDs); # checked
 =09
-	$WeBWorK::timer->continue("DB: pull out set/problem IDs start") if defi=
ned($WeBWorK::timer);
+	debug("DB: pull out set/problem IDs start");
 	my @globalProblemIDs =3D map { [ $_->[1], $_->[2] ] } @userProblemIDs;
-	$WeBWorK::timer->continue("DB: getGlobalProblems start") if defined($We=
BWorK::timer);
+	debug("DB: getGlobalProblems start");
 	my @GlobalProblems =3D $self->getGlobalProblems(@globalProblemIDs); # c=
hecked
 =09
-	$WeBWorK::timer->continue("DB: calc common fields start") if defined($W=
eBWorK::timer);
+	debug("DB: calc common fields start");
 	my %globalProblemFields =3D map { $_ =3D> 1 } $self->newGlobalProblem->=
FIELDS;
 	my @commonFields =3D grep { exists $globalProblemFields{$_} } $self->ne=
wUserProblem->FIELDS;
 =09
-	$WeBWorK::timer->continue("DB: merge start") if defined($WeBWorK::timer=
);
+	debug("DB: merge start");
 	for (my $i =3D 0; $i < @UserProblems; $i++) {
 		my $UserProblem =3D $UserProblems[$i];
 		my $GlobalProblem =3D $GlobalProblems[$i];
@@ -2275,7 +2268,7 @@
 			$UserProblem->$field($GlobalProblem->$field);
 		}
 	}
-	$WeBWorK::timer->continue("DB: merge done!") if defined($WeBWorK::timer=
);
+	debug("DB: merge done!");
 =09
 	return @UserProblems;
 }
@@ -2295,8 +2288,7 @@
 		    and defined $userProblemIDs[$i]->[3] );
     }
 =09
-    $WeBWorK::timer->continue("DB: getUserProblems start")=20
-	if defined($WeBWorK::timer);
+    debug("DB: getUserProblems start");
=20
 # these are triples [user_id, set_id, problem_id]
     my @nonversionedProblemIDs =3D map {[$_->[0],$_->[1],$_->[3]]} @user=
ProblemIDs;
@@ -2311,24 +2303,20 @@
 #    both of these, replacing global values with template values and not=
=20
 #    taking either in the event that the versioned problem already has a=
=20
 #    value for the field in question
-    $WeBWorK::timer->continue("DB: pull out set/problem IDs start")=20
-	if defined($WeBWorK::timer);
+    debug("DB: pull out set/problem IDs start");
     my @globalProblemIDs =3D map { [ $_->[1], $_->[2] ] } @nonversionedP=
roblemIDs;
-    $WeBWorK::timer->continue("DB: getGlobalProblems start")=20
-	if defined($WeBWorK::timer);
+    debug("DB: getGlobalProblems start");
     my @GlobalProblems =3D $self->getGlobalProblems( @globalProblemIDs )=
;
-    $WeBWorK::timer->continue("DB: getTemplateProblems start")=20
-	if defined($WeBWorK::timer);
+    debug("DB: getTemplateProblems start");
     my @TemplateProblems =3D $self->getUserProblems( @nonversionedProble=
mIDs );
 =09
-    $WeBWorK::timer->continue("DB: calc common fields start")=20
-	if defined($WeBWorK::timer);
+    debug("DB: calc common fields start");
=20
     my %globalProblemFields =3D map { $_ =3D> 1 } $self->newGlobalProble=
m->FIELDS;
     my @commonFields =3D=20
 	grep { exists $globalProblemFields{$_} } $self->newUserProblem->FIELDS;
 =09
-    $WeBWorK::timer->continue("DB: merge start") if defined($WeBWorK::ti=
mer);
+    debug("DB: merge start");
     for (my $i =3D 0; $i < @versionUserProblems; $i++) {
 	my $UserProblem =3D $versionUserProblems[$i];
 	my $GlobalProblem =3D $GlobalProblems[$i];
@@ -2346,7 +2334,7 @@
 		     $TemplateProblem->$field ne '' );
 	}
     }
-    $WeBWorK::timer->continue("DB: merge done!") if defined($WeBWorK::ti=
mer);
+    debug("DB: merge done!");
=20
     return @versionUserProblems;
 }
Index: ContentGenerator.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator.pm,v
retrieving revision 1.144
retrieving revision 1.145
diff -Llib/WeBWorK/ContentGenerator.pm -Llib/WeBWorK/ContentGenerator.pm =
-u -r1.144 -r1.145
--- lib/WeBWorK/ContentGenerator.pm
+++ lib/WeBWorK/ContentGenerator.pm
@@ -48,8 +48,9 @@
 use CGI::Pretty qw(*ul *li escapeHTML);
 use Date::Format;
 use URI::Escape;
-use WeBWorK::Template qw(template);
+use WeBWorK::Debug;
 use WeBWorK::PG;
+use WeBWorK::Template qw(template);
=20
 ########################################################################=
#######
=20
@@ -1304,7 +1305,7 @@
=20
 sub optionsMacro {
 	my ($self, %options) =3D @_;
-=09
+	debug("HELLO WORLD!");
 	my @options_to_show =3D @{$options{options_to_show}} if exists $options=
{options_to_show};
 	@options_to_show =3D "displayMode" unless @options_to_show;
 	my %options_to_show; @options_to_show{@options_to_show} =3D (); # make =
hash for easy lookups
--- lib/WeBWorK/Timing.pm
+++ /dev/null
@@ -1,248 +0,0 @@
-########################################################################=
########
-# WeBWorK Online Homework Delivery System
-# Copyright =A9 2000-2003 The WeBWorK Project, http://openwebwork.sf.net=
/
-# $CVSHeader: webwork2/lib/WeBWorK/Timing.pm,v 1.11 2005/07/29 21:25:24 =
gage Exp $
-#=20
-# This program is free software; you can redistribute it and/or modify i=
t under
-# the terms of either: (a) the GNU General Public License as published b=
y the
-# Free Software Foundation; either version 2, or (at your option) any la=
ter
-# version, or (b) the "Artistic License" which comes with this package.
-#=20
-# This program is distributed in the hope that it will be useful, but WI=
THOUT
-# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or =
FITNESS
-# FOR A PARTICULAR PURPOSE.  See either the GNU General Public License o=
r the
-# Artistic License for more details.
-########################################################################=
########
-
-package WeBWorK::Timing;
-
-=3Dhead1 NAME
-
-WeBWorK::Timing - Log timing data.
-
-head1 SYNOPSIS
-
- use WeBWorK::Timing;
-=20
- # Enable timing
- $WeBWorK::Timing::Enable =3D 1;
-=20
- # Log to a file instead of STDERR
- $WeBWorK::Timing::Logfile =3D "/path/to/timing.log";
-=20
- my $timer =3D WeBWorK::Timing->new("do some processesing");
- $timer->start;
- do_some_processing();
- $timer->continue("
- do_some_more_processing();
- $timer->stop;
- $timer->save;
-=20
- my $timer0 =3D WeBWorK::Timing->new("main task");
- my $timer1 =3D WeBWorK::Timing->new("subtask 1");
- my $timer2 =3D WeBWorK::Timing->new("subtask 1");
-=20
- $timer0->start;
- $timer1->start;
- sub_task(1);
- $timer1->stop;
- $timer2->start;
- sub_task(2);
- $timer2->stop;
- $timer0->stop;
-
- # timing data is saved when objects go out of scope
-
-=3Dcut
-
-use strict;
-use warnings;
-use Time::HiRes qw(gettimeofday tv_interval);
-
-our $TASK_COUNT =3D 0; # number of tasks processed in this child process
-
-########################################################################=
########
-
-=3Dhead1 CONFIGURATION VARIABLES
-
-=3Dover
-
-=3Ditem $Enabled
-
-If true, timing messages will be output. If false, they will be ignored.
-
-=3Dcut
-
-our $Enabled =3D 0  unless defined $Enabled;
-
-=3Ditem $Logfile
-
-If non-empty, timing output will be sent to the file named rather than S=
TDERR.
-
-=3Dcut
-
-our $Logfile =3D "" unless defined $Logfile;
-
-=3Dback
-
-=3Dcut
-
-########################################################################=
########
-
-=3Dhead1 CONSTRUCTOR
-
-=3Dover
-
-=3Ditem new($task)
-
-C<new> creates a new timing object, with the task given in $task.
-
-=3Dcut
-
-sub new {
-	my ($invocant, $task) =3D @_;
-	my $self =3D {
-		id    =3D> $TASK_COUNT++,
-		task  =3D> $task,
-		ctime =3D> scalar gettimeofday(),
-		saved =3D> 0,
-	};
-	return bless $self, ref $invocant || $invocant
-}
-
-=3Dback
-
-=3Dcut
-
-########################################################################=
########
-
-=3Dhead1 METHODS
-
-=3Dover
-
-=3Ditem start(), begin()
-
-Marks the current time as the start time for the task.
-
-=3Dcut
-
-sub start {
-	my ($self) =3D @_;
-	$self->{start} =3D gettimeofday();
-}
-
-sub begin { shift->start(@_); }
-
-=3Ditem continue($data)
-
-Stores the current time as an intermediate time, associated with the str=
ing
-given in $data.
-
-=3Dcut
-
-sub continue {
-	my ($self, $data) =3D @_;
-	push @{$self->{steps}}, [ scalar gettimeofday(), $data ];
-}
-
-=3Ditem stop(), finish(), end()
-
-Marks the current time as the stop time for the task.
-
-=3Dcut
-
-sub stop {
-	my ($self) =3D @_;
-	$self->{stop} =3D gettimeofday();
-}
-
-sub finish { shift->stop(@_); }
-sub end    { shift->stop(@_); }
-
-=3Ditem save()
-
-Writes the timing data for this task to the standard error stream. If sa=
ve is
-not called explicitly, it is called when the object goes out of scope.
-
-=3Dcut
-
-sub save {
-	my ($self) =3D @_;
-=09
-	if ($Enabled) {
-	    local($|=3D1); #flush after each print
-		my $fh;
-		if ($Logfile ne "") {=20
-			if (open my $tmpFH, ">>", $Logfile) {
-				$fh =3D $tmpFH;
-			} else {
-				warn "Failed to open timing log '$Logfile' in append mode: $!";
-				$fh =3D *STDERR;
-			}
-		} else {
-			$fh =3D *STDERR;
-		}
-	=09
-		my $id =3D $self->{id};
-		my $task =3D $self->{task};
-		my $now =3D gettimeofday();
-	=09
-		my $diff =3D sprintf("%.6f", 0);
-		if ($self->{start}) {
-			my $start =3D sprintf("%.6f", $self->{start});
-			print $fh "TIMING $$ $id $start ($diff) $task: START\n";
-		} else {
-			my $ctime =3D sprintf("%.6f", $self->{ctime});
-			print $fh "TIMING $$ $id $ctime ($diff) $task: START (assumed)\n";
-		}
-	=09
-		if ($self->{steps}) {
-			my @steps =3D @{$self->{steps}};
-			foreach my $step (@steps) {
-				my ($time, $data) =3D @$step;
-				$time =3D sprintf("%.6f", $time);
-				my $start =3D sprintf("%.6f", $self->{start});
-				my $diff  =3D sprintf("%.6f", $time-$start);
-				print $fh "TIMING $$ $id $time ($diff) $task: $data\n";
-			}
-		}
-	=09
-		if ($self->{stop}) {
-			my $stop =3D sprintf("%.6f", $self->{stop});
-			my $start =3D sprintf("%.6f", $self->{start});
-			my $diff =3D sprintf("%.6f", $stop-$start);
-			print $fh "TIMING $$ $id $stop ($diff) $task: END\n";
-		} else {
-			$now =3D sprintf("%.6f", $now);
-			my $start =3D sprintf("%.6f", $self->{start});
-			my $diff =3D sprintf("%.6f", $now-$start);
-			print $fh "TIMING $$ $id $now ($diff) $task: END (assumed)\n";
-		}
-	}
-=09
-	$self->{saved} =3D 1;
-}
-
-sub DESTROY {
-	my ($self) =3D shift;
-=09
-	$self->save unless $self->{saved};
-}
-
-=3Dback
-
-=3Dcut
-
-########################################################################=
########
-
-=3Dhead1 AUTHOR
-
-Written by Sam Hathaway, sh002i (at) math.rochester.edu.
-
-=3Dhead1 SEE ALSO
-
-The F<timing> utility can be used to parse and sort log output.
-
-=3Dcut
-
-1;
Index: Debug.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/Debug.pm,v
retrieving revision 1.4
retrieving revision 1.5
diff -Llib/WeBWorK/Debug.pm -Llib/WeBWorK/Debug.pm -u -r1.4 -r1.5
--- lib/WeBWorK/Debug.pm
+++ lib/WeBWorK/Debug.pm
@@ -40,6 +40,7 @@
=20
 use strict;
 use warnings;
+use Time::HiRes qw/gettimeofday/;
=20
 ########################################################################=
########
=20
@@ -65,12 +66,22 @@
=20
 =3Ditem $QuellSubroutineOutput
=20
-Prevent subroutines matching the following regular expression from loggi=
ng.
+If defined, prevent subroutines matching the following regular expressio=
n from
+logging.
=20
 =3Dcut
=20
 our $QuellSubroutineOutput;
=20
+=3Ditem $AllowSubroutineOutput
+
+If defined, allow only subroutines matching the following regular expres=
sion to
+log.
+
+=3Dcut
+
+our $AllowSubroutineOutput;
+
 =3Dback
=20
 =3Dcut
@@ -92,11 +103,14 @@
 =09
 	if ($Enabled) {
 		my ($package, $filename, $line, $subroutine) =3D caller(1);
+		return if defined $AllowSubroutineOutput and not $subroutine =3D~ m/$A=
llowSubroutineOutput/;
 		return if defined $QuellSubroutineOutput and $subroutine =3D~ m/$Quell=
SubroutineOutput/;
 	=09
-		my $finalMessage =3D "$subroutine: " . join("", @message);
+		my ($sec, $msec) =3D gettimeofday;
+		my $date =3D time2str("%a %b %d %H:%M:%S.$msec %Y", $sec);
+		my $finalMessage =3D "[$date] $subroutine: " . join("", @message);
 		$finalMessage .=3D "\n" unless $finalMessage =3D~ m/\n$/;
-		$finalMessage =3D "[" . time2str("%a %b %d %H:%M:%S %Y", time) . "] " =
.$finalMessage;
+	=09
 		if ($WeBWorK::Debug::Logfile ne "") {
 			if (open my $fh, ">>", $Logfile) {
 				print $fh $finalMessage;
Index: URLPath.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/URLPath.pm,v
retrieving revision 1.24
retrieving revision 1.25
diff -Llib/WeBWorK/URLPath.pm -Llib/WeBWorK/URLPath.pm -u -r1.24 -r1.25
--- lib/WeBWorK/URLPath.pm
+++ lib/WeBWorK/URLPath.pm
@@ -24,12 +24,17 @@
=20
 use strict;
 use warnings;
+use WeBWorK::Debug;
=20
-sub debug {
-#	my ($label, $indent, @message) =3D @_;
-#	print STDERR " "x$indent;
-#	print STDERR "$label: " if $label ne "";
-#	print STDERR @message;
+{
+	no warnings "redefine";
+=09
+	sub debug {
+		my ($label, $indent, @message) =3D @_;
+		my $header =3D " "x$indent;
+		$header .=3D "$label: " if $label ne "";
+		WeBWorK::Debug::debug($header, @message);
+	}
 }
=20
 =3Dhead1 VIRTUAL HEIRARCHY
@@ -897,10 +902,10 @@
=20
 sub visitPathTypeNode($$$$) {
 	my ($nodeID, $path, $argsRef, $indent) =3D @_;
-	debug("visitPathTypeNode", $indent, "visiting node $nodeID with path $p=
ath\n");
+	debug("visitPathTypeNode", $indent, "visiting node $nodeID with path $p=
ath");
 =09
 	unless (exists $pathTypes{$nodeID}) {
-		debug("visitPathTypeNode", $indent, "node $nodeID doesn't exist in nod=
e list: failed\n");
+		debug("visitPathTypeNode", $indent, "node $nodeID doesn't exist in nod=
e list: failed");
 		die "node $nodeID doesn't exist in node list: failed";
 	}
 =09
@@ -913,7 +918,7 @@
 	if ($path =3D~ s/($match)//) {
 		# it matches! store captured strings in $argsRef and remove the matche=
d
 		# characters from $path. waste a lot of lines on sanity checking... ;)
-		debug("", 0, "success!\n");
+		debug("", 0, "success!");
 		my @capture_values =3D $1 =3D~ m/$match/;
 		if (@capture_names) {
 			my $nexpected =3D @capture_names;
@@ -935,13 +940,13 @@
 					my $old =3D $argsRef->{$name};
 					warn "encountered argument $name again, old value: $old new value: =
$value -- replacing.";
 				}
-				debug("visitPathTypeNode", $indent, "setting argument $name =3D> $va=
lue.\n");
+				debug("visitPathTypeNode", $indent, "setting argument $name =3D> $va=
lue.");
 				$argsRef->{$name} =3D $value;
 			}
 		}
 	} else {
 		# it doesn't match. bail out now with return value 0
-		debug("", 0, "failed.\n");
+		debug("", 0, "failed.");
 		return 0;
 	}
 =09
@@ -949,16 +954,16 @@
 =09
 	# if there's no more path left, then this node is the one! return $node=
ID
 	if ($path eq "") {
-		debug("visitPathTypeNode", $indent, "no path left, type is $nodeID\n")=
;
+		debug("visitPathTypeNode", $indent, "no path left, type is $nodeID");
 		return $nodeID;
 	}
 =09
 	# otherwise, we have to send the remaining path to the node's children
-	debug("visitPathTypeNode", $indent, "but path remains: $path\n");
+	debug("visitPathTypeNode", $indent, "but path remains: $path");
 	my @kids =3D @{ $node{kids} };
 	if (@kids) {
 		foreach my $kid (@kids) {
-			debug("visitPathTypeNode", $indent, "trying child $kid:\n");
+			debug("visitPathTypeNode", $indent, "trying child $kid:");
 			my $result =3D visitPathTypeNode($kid, $path, $argsRef, $indent+1);
 			# we return in two situations:
 			# if $result is -1, then the kid matched but couldn't consume the res=
t of the path
@@ -966,9 +971,9 @@
 			# these are all true values (assuming that "0" isn't a valid node ID)=
, so we say:
 			return $result if $result;
 		}
-		debug("visitPathTypeNode", $indent, "no children claimed the remaining=
 path: failed.\n");
+		debug("visitPathTypeNode", $indent, "no children claimed the remaining=
 path: failed.");
 	} else {
-		debug("visitPathTypeNode", $indent, "no children to claim the remainin=
g path: failed.\n");
+		debug("visitPathTypeNode", $indent, "no children to claim the remainin=
g path: failed.");
 	}
 =09
 	# in both of the above cases, we matched but couldn't provide children =
that
Index: Constants.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/Constants.pm,v
retrieving revision 1.27
retrieving revision 1.28
diff -Llib/WeBWorK/Constants.pm -Llib/WeBWorK/Constants.pm -u -r1.27 -r1.=
28
--- lib/WeBWorK/Constants.pm
+++ lib/WeBWorK/Constants.pm
@@ -37,24 +37,21 @@
 #=20
 $WeBWorK::Debug::Logfile =3D "";
=20
-# Prevent subroutines matching the following regular expression from log=
ging.
+# If defined, prevent subroutines matching the following regular express=
ion from
+# logging.
 #=20
 # For example, this pattern prevents the dispatch() function from loggin=
g:
 #     $WeBWorK::Debug::QuellSubroutineOutput =3D qr/^WeBWorK::dispatch$/=
;
 #=20
 $WeBWorK::Debug::QuellSubroutineOutput =3D undef;
=20
-########################################################################=
########
-# WeBWorK::Timing
-########################################################################=
########
-
-# If true, WeBWorK::Timing will print timing data.
+# If defined, allow only subroutines matching the following regular expr=
ession
+# to log.
 #=20
-$WeBWorK::Timing::Enabled =3D 0;
-
-# If non-empty, timing data will be sent to the file named rather than S=
TDERR.
+# For example, this pattern allow only some function being worked on to =
log:
+#     $WeBWorK::Debug::AllowSubroutineOutput =3D qr/^WeBWorK::SomePkg::m=
yFunc$/;
 #=20
-$WeBWorK::Timing::Logfile =3D "";
+$WeBWorK::Debug::AllowSubroutineOutput =3D undef;
=20
 ########################################################################=
########
 # WeBWorK::ContentGenerator::Hardcopy
Index: WeBWorK.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK.pm,v
retrieving revision 1.72
retrieving revision 1.73
diff -Llib/WeBWorK.pm -Llib/WeBWorK.pm -u -r1.72 -r1.73
--- lib/WeBWorK.pm
+++ lib/WeBWorK.pm
@@ -51,10 +51,9 @@
 use WeBWorK::DB;
 use WeBWorK::Debug;
 use WeBWorK::Request;
-use WeBWorK::Timing;
 use WeBWorK::Upload;
 use WeBWorK::URLPath;
-use WeBWorK::Utils qw(runtime_use writeTimingLogEntry);
+use WeBWorK::Utils qw(runtime_use);
 use Date::Format;
=20
 use constant AUTHEN_MODULE =3D> "WeBWorK::ContentGenerator::Login";
@@ -164,13 +163,6 @@
 =09
 	debug(("-" x 80) . "\n");
 =09
-	# create a package-global timing object
-	# FIXME: this is used by other modules!
-	# FIXME: this is not thread-safe!
-	my $label =3D defined $displayArgs{courseID} ? $displayArgs{courseID} :=
 "ROOT";
-	$WeBWorK::timer =3D WeBWorK::Timing->new($label);
-	$WeBWorK::timer->start;
-=09
 	debug("We need to get a course environment (with or without a courseID!=
)\n");
 	my $ce =3D eval { new WeBWorK::CourseEnvironment({
 		#webworkRoot =3D> $r->dir_config("webwork_root"),
@@ -296,11 +288,6 @@
 	debug(("-" x 80) . "\n");
 	debug("Finally, we'll load the display module...\n");
 =09
-	# The "production timer" uses a finer grained HiRes timing module
-	# rather than the standard unix "time".
-	#my $localStartTime =3D time;
-	my $productionTimer =3D WeBWorK::Timing->new($label);
-	$productionTimer->start();
 	runtime_use($displayModule);
 =09
 	debug("...instantiate it...\n");
@@ -315,17 +302,8 @@
 	debug("-------------------- call to ${displayModule}::go\n");
 =09
 	debug("returning result: " . (defined $result ? $result : "UNDEF") . "\=
n");
-	#$WeBWorK::timer->continue("[" . time2str("%a %b %d %H:%M:%S %Y", time)=
 . "]" . "[" . $r->uri . "]");
-	#$WeBWorK::timer->stop();
-	#$WeBWorK::timer->save();
-=09
-	#my $localStopTime =3D time;
-	$productionTimer->stop();
-	#my $timeDiff =3D $localStopTime - $localStartTime;
-	my $productionTimeDiff    =3D $productionTimer->{stop} - $productionTim=
er->{start};=20
-	writeTimingLogEntry($ce,"[".$r->uri."]", sprintf("runTime =3D %.3f sec"=
, $productionTimeDiff)." ".$ce->{dbLayoutName},"" );
-	return $result;
 =09
+	return $result;
 }
=20
 sub mungeParams {
Index: Problem.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Probl=
em.pm,v
retrieving revision 1.178
retrieving revision 1.179
diff -Llib/WeBWorK/ContentGenerator/Problem.pm -Llib/WeBWorK/ContentGener=
ator/Problem.pm -u -r1.178 -r1.179
--- lib/WeBWorK/ContentGenerator/Problem.pm
+++ lib/WeBWorK/ContentGenerator/Problem.pm
@@ -27,13 +27,13 @@
 use warnings;
 use CGI qw();
 use File::Path qw(rmtree);
+use WeBWorK::Debug;
 use WeBWorK::Form;
 use WeBWorK::PG;
 use WeBWorK::PG::ImageGenerator;
 use WeBWorK::PG::IO;
 use WeBWorK::Utils qw(readFile writeLog writeCourseLog encodeAnswers dec=
odeAnswers ref2string makeTempDirectory);
 use WeBWorK::DB::Utils qw(global2user user2global findDefaults);
-use WeBWorK::Timing;
 use URI::Escape;
=20
 use WeBWorK::Utils::Tasks qw(fake_set fake_problem);
@@ -592,7 +592,7 @@
 =09
 	##### translation #####
=20
-	$WeBWorK::timer->continue("begin pg processing") if defined($WeBWorK::t=
imer);
+	debug("begin pg processing");
 	my $pg =3D WeBWorK::PG->new(
 		$ce,
 		$effectiveUser,
@@ -610,7 +610,7 @@
 		},
 	);
 =09
-	$WeBWorK::timer->continue("end pg processing") if defined($WeBWorK::tim=
er);
+	debug("end pg processing");
 =09
 	##### fix hint/solution options #####
 =09
@@ -822,7 +822,7 @@
 	}
 =09
 	##### answer processing #####
-	$WeBWorK::timer->continue("begin answer processing") if defined($WeBWor=
K::timer);
+	debug("begin answer processing");
 	# if answers were submitted:
 	my $scoreRecordedMessage;
 	my $pureProblem;
@@ -926,7 +926,7 @@
 		}
 	}
 =09
-	$WeBWorK::timer->continue("end answer processing") if defined($WeBWorK:=
:timer);
+	debug("end answer processing");
 =09
 	##### output #####
 	# custom message for editor
Index: GatewayQuiz.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Gatew=
ayQuiz.pm,v
retrieving revision 1.11
retrieving revision 1.12
diff -Llib/WeBWorK/ContentGenerator/GatewayQuiz.pm -Llib/WeBWorK/ContentG=
enerator/GatewayQuiz.pm -u -r1.11 -r1.12
--- lib/WeBWorK/ContentGenerator/GatewayQuiz.pm
+++ lib/WeBWorK/ContentGenerator/GatewayQuiz.pm
@@ -34,7 +34,6 @@
 use WeBWorK::PG::IO;
 use WeBWorK::Utils qw(writeLog writeCourseLog encodeAnswers decodeAnswer=
s ref2string makeTempDirectory);
 use WeBWorK::DB::Utils qw(global2user user2global findDefaults);
-use WeBWorK::Timing;
=20
 use WeBWorK::ContentGenerator::Instructor qw(assignSetVersionToUser);
=20
@@ -1016,8 +1015,7 @@
 # answer processing
 ####################################
=20
-    $WeBWorK::timer->continue("begin answer processing")=20
-	if defined($WeBWorK::timer);
+    debug("begin answer processing");=20
=20
     my @scoreRecordedMessage =3D ('') x scalar(@problems);
=20
@@ -1165,8 +1163,7 @@
 # warn("in submitanswers conditional\n");
=20
     } # end if submitAnswers conditional
-    $WeBWorK::timer->continue("end answer processing")=20
-	if defined( $WeBWorK::timer );
+    debug("end answer processing");
=20
 # additional set-level database manipulation: this is all for versioned=20
 #    sets/gateway tests
Index: ProblemSets.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Probl=
emSets.pm,v
retrieving revision 1.60
retrieving revision 1.61
diff -Llib/WeBWorK/ContentGenerator/ProblemSets.pm -Llib/WeBWorK/ContentG=
enerator/ProblemSets.pm -u -r1.60 -r1.61
--- lib/WeBWorK/ContentGenerator/ProblemSets.pm
+++ lib/WeBWorK/ContentGenerator/ProblemSets.pm
@@ -26,6 +26,7 @@
 use strict;
 use warnings;
 use CGI qw();
+use WeBWorK::Debug;
 use WeBWorK::Utils qw(readFile sortByName);
=20
 # what do we consider a "recent" problem set?
@@ -135,10 +136,10 @@
 	my @setIDs =3D $db->listUserSets($effectiveUser);
 =09
 	my @userSetIDs =3D map {[$effectiveUser, $_]} @setIDs;
-	$WeBWorK::timer->continue("Begin collecting merged sets") if defined($W=
eBWorK::timer);
+	debug("Begin collecting merged sets");
 	my @sets =3D $db->getMergedSets( @userSetIDs );
 =09
-	$WeBWorK::timer->continue("Begin fixing merged sets") if defined($WeBWo=
rK::timer);
+	debug("Begin fixing merged sets");
 =09
 	# Database fix (in case of undefined published values)
 	# this may take some extra time the first time but should NEVER need to=
 be run twice
@@ -157,7 +158,7 @@
=20
 # gateways/versioned sets require dealing with output data slightly=20
 # differently, so check for those here=09
-	$WeBWorK::timer->continue("Begin set-type check") if defined($WeBWorK::=
timer);
+	debug("Begin set-type check");
 	my $existVersions =3D 0;
 	foreach ( @sets ) {
 	    if ( defined( $_->assignment_type() ) &&=20
@@ -200,12 +201,12 @@
 	        );
 	}
=20
-	$WeBWorK::timer->continue("Begin sorting merged sets") if defined($WeBW=
orK::timer);
+	debug("Begin sorting merged sets");
 =09
 	@sets =3D sortByName("set_id", @sets) if $sort eq "name";
 	@sets =3D sort byUrgency @sets if $sort eq "status";
 =09
-	$WeBWorK::timer->continue("End preparing merged sets") if defined($WeBW=
orK::timer);
+	debug("End preparing merged sets");
 =09
 	foreach my $set (@sets) {
 		die "set $set not defined" unless $set;
Index: ProblemSet.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Probl=
emSet.pm,v
retrieving revision 1.65
retrieving revision 1.66
diff -Llib/WeBWorK/ContentGenerator/ProblemSet.pm -Llib/WeBWorK/ContentGe=
nerator/ProblemSet.pm -u -r1.65 -r1.66
--- lib/WeBWorK/ContentGenerator/ProblemSet.pm
+++ lib/WeBWorK/ContentGenerator/ProblemSet.pm
@@ -28,8 +28,8 @@
 use warnings;
 use CGI qw(*ul *li);
 use WeBWorK::PG;
-use WeBWorK::Timing;
 use URI::Escape;
+use WeBWorK::Debug;
 use WeBWorK::Utils qw(sortByName);
=20
 sub initialize {
@@ -147,7 +147,7 @@
 	print CGI::start_ul();
=20
 	# FIXME: setIDs contain no info on published/unpublished so unpublished=
 sets are still printed
-	$WeBWorK::timer->continue("Begin printing sets from listUserSets()") if=
 defined $WeBWorK::timer;
+	debug("Begin printing sets from listUserSets()");
 	foreach my $setID (@setIDs) {
 		my $setPage =3D $urlpath->newFromModule("WeBWorK::ContentGenerator::Pr=
oblemSet",
 			courseID =3D> $courseID, setID =3D> $setID);
@@ -157,17 +157,17 @@
 									}}, $setID)
 	    ) ;
 	}
-	$WeBWorK::timer->continue("End printing sets from listUserSets()") if d=
efined $WeBWorK::timer;
+	debug("End printing sets from listUserSets()");
=20
 	# FIXME: when database calls are faster, this will get rid of unpublish=
ed sibling links
-	#$WeBWorK::timer->continue("Begin printing sets from getMergedSets()") =
if defined $WeBWorK::timer;=09
+	#debug("Begin printing sets from getMergedSets()");=09
 	#my @userSetIDs =3D map {[$eUserID, $_]} @setIDs;
 	#my @sets =3D $db->getMergedSets(@userSetIDs);
 	#foreach my $set (@sets) {
 	#	my $setPage =3D $urlpath->newFromModule("WeBWorK::ContentGenerator::P=
roblemSet", courseID =3D> $courseID, setID =3D> $set->set_id);
 	#	print CGI::li(CGI::a({href=3D>$self->systemLink($setPage)}, $set->set=
_id)) unless !(defined $set && ($set->published || $authz->hasPermissions=
($user, "view_unpublished_sets"));
 	#}
-	#$WeBWorK::timer->continue("Begin printing sets from getMergedSets()") =
if defined $WeBWorK::timer;
+	#debug("Begin printing sets from getMergedSets()");
 =09
 	print CGI::end_ul();
 	print CGI::end_li();
Index: Hardcopy.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Hardc=
opy.pm,v
retrieving revision 1.57
retrieving revision 1.58
diff -Llib/WeBWorK/ContentGenerator/Hardcopy.pm -Llib/WeBWorK/ContentGene=
rator/Hardcopy.pm -u -r1.57 -r1.58
--- lib/WeBWorK/ContentGenerator/Hardcopy.pm
+++ lib/WeBWorK/ContentGenerator/Hardcopy.pm
@@ -43,12 +43,11 @@
 use CGI qw();
 use File::Path qw(rmtree);
 use WeBWorK::Form;
+use WeBWorK::Debug;
 use WeBWorK::PG;
 use WeBWorK::Utils qw(readFile makeTempDirectory);
 use Apache::Constants qw(:common REDIRECT);
=20
-our $HardcopyTimer =3D new WeBWorK::Timing if $WeBWorK::Timing::Enabled;
-
 =3Dhead1 CONFIGURATION VARIABLES
=20
 =3Dover
@@ -73,7 +72,8 @@
 	my $authz =3D $r->authz;
 	my $userID  =3D $r->param("user");
 =09
-	$HardcopyTimer->start if $WeBWorK::Timing::Enabled;;
+	debug("begin hardcopy processing");
+=09
 	my $singleSet       =3D $r->urlpath->arg("setID");
 	my @sets            =3D $r->param("hcSet");
 	my @users           =3D $r->param("hcUser");
@@ -188,19 +188,18 @@
 sub body {
 	my ($self) =3D @_;
 =09
-	$HardcopyTimer->continue("Hardcopy: printing generation errors") if def=
ined($HardcopyTimer);
+	debug("Hardcopy: printing generation errors");
+=09
 	if ($self->{generationError}) {
 		if (ref $self->{generationError} eq "ARRAY") {
 			my ($disposition, @rest) =3D @{$self->{generationError}};
 			if ($disposition eq "PGFAIL") {
 				$self->multiErrorOutput(@{$self->{errors}});
-				$HardcopyTimer->continue("Hardcopy: end printing generation errors")=
 if defined($HardcopyTimer);
-	            $HardcopyTimer->save if defined($HardcopyTimer);
+				debug("Hardcopy: end printing generation errors");
 				return "";
 			} elsif ($disposition eq "FAIL") {
 				print $self->errorOutput(@rest);
-				$HardcopyTimer->continue("Hardcopy: end printing generation errors")=
 if defined($HardcopyTimer);
-	            $HardcopyTimer->save if defined($HardcopyTimer);
+				debug("Hardcopy: end printing generation errors");
 				return "";
 			} elsif ($disposition eq "RETRY") {
 				print $self->errorOutput(@rest);
@@ -209,13 +208,11 @@
 			}
 		} else {
 			# not something we were expecting...
-			$HardcopyTimer->continue("Hardcopy: end printing generation errors") =
if defined($HardcopyTimer);
-	        $HardcopyTimer->save if defined($HardcopyTimer);
+			debug("Hardcopy: end printing generation errors");
 			die $self->{generationError};
 		}
 	}
-	$HardcopyTimer->continue("Hardcopy: end printing generation errors") if=
 defined($HardcopyTimer);
-	$HardcopyTimer->save if defined($HardcopyTimer);
+	debug("Hardcopy: end printing generation errors");
=20
 	if (@{$self->{warnings}}) {
 		# FIXME: this code will only be reached if there was also a
@@ -454,9 +451,9 @@
 	my $pdfFileURL =3D undef;
 	if ($self->{hardcopy_format} eq 'pdf' ) {
 		my $errors =3D '';
-		$HardcopyTimer->continue("begin latex2pdf") if defined($HardcopyTimer)=
;
+		debug("Hardcopy: format log file");
 		$pdfFileURL =3D eval { $self->latex2pdf($tex, $tempDir, $fileName) };
-		$HardcopyTimer->continue("end latex2pdf") if defined($HardcopyTimer);
+		debug("end latex2pdf");
 		if ($@) {
 			$errors =3D $@;
 			#$errors =3D~ s/\n/<br>/g;  # make this readable on HTML FIXME make t=
his a Utils. filter (Error2HTML)
@@ -581,12 +578,12 @@
 		if (-e $logFile) {
 			push @textErrorMessage , "pdflatex ran, but did not succeed. This sug=
gests an error in the TeX\n", CGI::br();
 			push @textErrorMessage , "version of one of the problems, or a proble=
m with the pdflatex system.\n",CGI::br();
-			$HardcopyTimer->continue("Hardcopy: read log file") if defined($Hardc=
opyTimer);
+			debug("Hardcopy: read log file");
 			my $logFileContents =3D eval { readTexErrorLog($logFile) };
 			$logFileContents    .=3D  CGI::hr().CGI::hr();
-			$HardcopyTimer->continue("Hardcopy: format log file") if defined($Har=
dcopyTimer);
+			debug("Hardcopy: format log file");
 			$logFileContents    .=3D eval { formatTexFile($texFile)     };
-			$HardcopyTimer->continue("Hardcopy: end processing log file") if defi=
ned($HardcopyTimer);
+			debug("Hardcopy: end processing log file");
 			if ($@) {
 				push @textErrorMessage, "Additionally, the pdflatex log file could n=
ot be read, though it exists.\n", CGI::br();
 			} else {
@@ -745,7 +742,7 @@
 }
=20
 sub getProblemTeX {
-    $HardcopyTimer ->continue("hardcopy: begin processing problem") if d=
efined($HardcopyTimer);
+    debug("hardcopy: begin processing problem");
 	my ($self, $effectiveUser, $setName, $problemNumber, $pgFile) =3D @_;
 	my $r      =3D $self->r;
 	my $ce     =3D $r->ce;
@@ -880,7 +877,7 @@
 			$pg->{body_text} .=3D $correctTeX;
 		}
 	}
-	$HardcopyTimer ->continue("hardcopy: end processing problem") if define=
d($HardcopyTimer);
+	debug("hardcopy: end processing problem");
 	return $pg->{body_text};
 }
=20
Index: Instructor.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Instr=
uctor.pm,v
retrieving revision 1.48
retrieving revision 1.49
diff -Llib/WeBWorK/ContentGenerator/Instructor.pm -Llib/WeBWorK/ContentGe=
nerator/Instructor.pm -u -r1.48 -r1.49
--- lib/WeBWorK/ContentGenerator/Instructor.pm
+++ lib/WeBWorK/ContentGenerator/Instructor.pm
@@ -29,6 +29,7 @@
 use CGI qw();
 use File::Find;
 use WeBWorK::DB::Utils qw(initializeUserProblem);
+use WeBWorK::Debug;
 use WeBWorK::Utils;
=20
 =3Dhead1 METHODS
@@ -286,13 +287,13 @@
 	my $db =3D $self->{db};
 	my @userIDs =3D $db->listUsers;
=20
-	$WeBWorK::timer->continue("$setID: getting user list") if defined $WeBW=
orK::timer;
+	debug("$setID: getting user list");
 	my @userRecords =3D $db->getUsers(@userIDs);
-	$WeBWorK::timer->continue("$setID: (done with that)") if defined $WeBWo=
rK::timer;
+	debug("$setID: (done with that)");
 =09
-	$WeBWorK::timer->continue("$setID: getting problem list") if defined $W=
eBWorK::timer;
+	debug("$setID: getting problem list");
 	my @GlobalProblems =3D grep { defined $_ } $db->getAllGlobalProblems($s=
etID);
-	$WeBWorK::timer->continue("$setID: (done with that)") if defined $WeBWo=
rK::timer;
+	debug("$setID: (done with that)");
 =09
 	my @results;
 =09
@@ -302,20 +303,20 @@
 		my $userID =3D $User->user_id;
 		$UserSet->user_id($userID);
 		$UserSet->set_id($setID);
-		$WeBWorK::timer->continue("$setID: adding UserSet for $userID") if def=
ined $WeBWorK::timer;
+		debug("$setID: adding UserSet for $userID");
 		eval { $db->addUserSet($UserSet) };
 		if ($@) {
 			next if $@ =3D~ m/user set exists/;
 			die $@;
 		}
-		$WeBWorK::timer->continue("$setID: (done with that)") if defined $WeBW=
orK::timer;
+		debug("$setID: (done with that)");
 	=09
-		$WeBWorK::timer->continue("$setID: adding UserProblems for $userID") i=
f defined $WeBWorK::timer;
+		debug("$setID: adding UserProblems for $userID");
 		foreach my $GlobalProblem (@GlobalProblems) {
 			my @result =3D $self->assignProblemToUser($userID, $GlobalProblem);
 			push @results, @result if @result;
 		}
-		$WeBWorK::timer->continue("$setID: (done with that)") if defined $WeBW=
orK::timer;
+		debug("$setID: (done with that)");
 	}
 =09
 	return @results;
Index: Grades.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Grade=
s.pm,v
retrieving revision 1.14
retrieving revision 1.15
diff -Llib/WeBWorK/ContentGenerator/Grades.pm -Llib/WeBWorK/ContentGenera=
tor/Grades.pm -u -r1.14 -r1.15
--- lib/WeBWorK/ContentGenerator/Grades.pm
+++ lib/WeBWorK/ContentGenerator/Grades.pm
@@ -27,9 +27,9 @@
 use strict;
 use warnings;
 use CGI qw();
-use WeBWorK::Utils qw(readDirectory list2hash max);
+use WeBWorK::Debug;
 use WeBWorK::DB::Record::Set;
-
+use WeBWorK::Utils qw(readDirectory list2hash max);
=20
 sub initialize {
 	my ($self) =3D @_;
@@ -268,15 +268,15 @@
 	    my $total      =3D 0;
 		my $num_of_attempts =3D 0;
 =09
-		$WeBWorK::timer->continue("Begin collecting problems for set $setName"=
) if defined($WeBWorK::timer);
+		debug("Begin collecting problems for set $setName");
 		my @problemRecords =3D $db->getAllUserProblems( $studentName, $setName=
 );
-		$WeBWorK::timer->continue("End collecting problems for set $setName") =
if defined($WeBWorK::timer);
+		debug("End collecting problems for set $setName");
 	=09
 		# FIXME the following line doesn't sort the problemRecords
 		#my @problems =3D sort {$a <=3D> $b } map { $_->problem_id } @problemR=
ecords;
-		$WeBWorK::timer->continue("Begin sorting problems for set $setName") i=
f defined($WeBWorK::timer);
+		debug("Begin sorting problems for set $setName");
 		@problemRecords =3D sort {$a->problem_id <=3D> $b->problem_id }  @prob=
lemRecords;
-		$WeBWorK::timer->continue("End sorting problems for set $setName") if =
defined($WeBWorK::timer);
+		debug("End sorting problems for set $setName");
 		my $num_of_problems  =3D @problemRecords;
 		my $max_problems     =3D defined($num_of_problems) ? $num_of_problems =
: 0;=20
 	=09
Index: UsersAssignedToSet.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Instr=
uctor/UsersAssignedToSet.pm,v
retrieving revision 1.17
retrieving revision 1.18
diff -Llib/WeBWorK/ContentGenerator/Instructor/UsersAssignedToSet.pm -Lli=
b/WeBWorK/ContentGenerator/Instructor/UsersAssignedToSet.pm -u -r1.17 -r1=
.18
--- lib/WeBWorK/ContentGenerator/Instructor/UsersAssignedToSet.pm
+++ lib/WeBWorK/ContentGenerator/Instructor/UsersAssignedToSet.pm
@@ -27,6 +27,7 @@
 use strict;
 use warnings;
 use CGI qw();
+use WeBWorK::Debug;
=20
 sub initialize {
 	my ($self)     =3D @_;
@@ -52,10 +53,10 @@
 		if ref $db->{set} eq "WeBWorK::DB::Schema::GlobalTableEmulator";
=20
 	if (defined $r->param('assignToAll')) {
-		$WeBWorK::timer->continue("assignSetToAllUsers($setID)") if defined $W=
eBWorK::timer;
+		debug("assignSetToAllUsers($setID)");
 		$self->addmessage(CGI::div({class=3D>'ResultsWithoutError'}, "Problems=
 have been assigned to all current users."));
 		$self->assignSetToAllUsers($setID);
-		$WeBWorK::timer->continue("done assignSetToAllUsers($setID)") if defin=
ed $WeBWorK::timer;
+		debug("done assignSetToAllUsers($setID)");
 	} elsif (defined $r->param('unassignFromAll') and defined($r->param('un=
assignFromAllSafety')) and $r->param('unassignFromAllSafety')=3D=3D1) {
 		%selectedUsers =3D ( $globalUserID =3D> 1 );
 		$self->addmessage(CGI::div({class=3D>'ResultsWithoutError'}, "Problems=
 for all students have been unassigned."));
@@ -76,9 +77,9 @@
 		foreach my $selectedUser (@users) {
 			if (exists $selectedUsers{$selectedUser}) {
 				unless ($setUsers{$selectedUser}) {	# skip users already in the set
-					$WeBWorK::timer->continue("assignSetToUser($selectedUser, ...)") if=
 defined $WeBWorK::timer;
+					debug("assignSetToUser($selectedUser, ...)");
 					$self->assignSetToUser($selectedUser, $setRecord);
-					$WeBWorK::timer->continue("done assignSetToUser($selectedUser, ...)=
") if defined $WeBWorK::timer;
+					debug("done assignSetToUser($selectedUser, ...)");
 				}
 			} else {
 				next if $selectedUser eq $globalUserID;
Index: Stats.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Instr=
uctor/Stats.pm,v
retrieving revision 1.55
retrieving revision 1.56
diff -Llib/WeBWorK/ContentGenerator/Instructor/Stats.pm -Llib/WeBWorK/Con=
tentGenerator/Instructor/Stats.pm -u -r1.55 -r1.56
--- lib/WeBWorK/ContentGenerator/Instructor/Stats.pm
+++ lib/WeBWorK/ContentGenerator/Instructor/Stats.pm
@@ -27,9 +27,11 @@
 use strict;
 use warnings;
 use CGI qw();
-use WeBWorK::Utils qw(readDirectory list2hash max sortByName);
-use WeBWorK::DB::Record::Set;
+use WeBWorK::Debug;
 use WeBWorK::ContentGenerator::Grades;
+use WeBWorK::DB::Record::Set;
+use WeBWorK::Utils qw(readDirectory list2hash max sortByName);
+
 # The table format has been borrowed from the Grades.pm module
 sub initialize {
 	my $self     =3D shift;=20
@@ -300,10 +302,10 @@
 =09
 	my $max_num_problems  =3D 0;
 	# get user records
-	$WeBWorK::timer->continue("Begin obtaining user records for set $setNam=
e") if defined($WeBWorK::timer);
+	debug("Begin obtaining problem records for user $student set $setName")=
;
 	my @userRecords  =3D $db->getUsers(@studentList);
-	$WeBWorK::timer->continue("End obtaining user records for set $setName"=
) if defined($WeBWorK::timer);
-    $WeBWorK::timer->continue("begin main loop") if defined($WeBWorK::ti=
mer);
+	debug("End obtaining user records for set $setName");
+    debug("begin main loop");
  	my @augmentedUserRecords    =3D ();
  	my $number_of_active_students;
    =20
@@ -332,10 +334,10 @@
 		my %h_problemData   =3D ();
 		my $probNum         =3D 0;
 	=09
-		$WeBWorK::timer->continue("Begin obtaining problem records for user $s=
tudent set $setName") if defined($WeBWorK::timer);
+		debug("Begin obtaining problem records for user $student set $setName"=
);
 	=09
 		my @problemRecords =3D sort {$a->problem_id <=3D> $b->problem_id } $db=
->getAllUserProblems( $student, $setName );
-		$WeBWorK::timer->continue("End obtaining problem records for user $stu=
dent set $setName") if defined($WeBWorK::timer);
+		debug("End obtaining problem records for user $student set $setName");
 		my $num_of_problems =3D @problemRecords;
 		$max_num_problems =3D ($max_num_problems>=3D $num_of_problems) ? $max_=
num_problems : $num_of_problems;
 	   ########################################
@@ -459,7 +461,7 @@
 		push( @augmentedUserRecords, $temp_hash );
 		                               =20
 	}=09
-	$WeBWorK::timer->continue("end mainloop") if defined($WeBWorK::timer);
+	debug("end mainloop");
 =09
 	@augmentedUserRecords =3D sort {           &$sort_method($a,$b)
 												||
Index: Scoring.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Instr=
uctor/Scoring.pm,v
retrieving revision 1.48
retrieving revision 1.49
diff -Llib/WeBWorK/ContentGenerator/Instructor/Scoring.pm -Llib/WeBWorK/C=
ontentGenerator/Instructor/Scoring.pm -u -r1.48 -r1.49
--- lib/WeBWorK/ContentGenerator/Instructor/Scoring.pm
+++ lib/WeBWorK/ContentGenerator/Instructor/Scoring.pm
@@ -26,10 +26,9 @@
 use strict;
 use warnings;
 use CGI qw();
+use WeBWorK::Debug;
 use WeBWorK::Utils qw(readFile);
 use WeBWorK::DB::Utils qw(initializeUserProblem);
-use WeBWorK::Timing;
-
=20
 our @userInfoColumnHeadings =3D ("STUDENT ID", "login ID", "LAST NAME", =
"FIRST NAME", "SECTION", "RECITATION");
 our @userInfoFields =3D ("student_id", "user_id","last_name", "first_nam=
e", "section", "recitation");
@@ -63,7 +62,7 @@
 		my $recordSingleSetScores  =3D $r->param('recordSingleSetScores');
 	=09
 		# pre-fetch users
-		$WeBWorK::timer->continue("pre-fetching users") if defined($WeBWorK::t=
imer);
+		debug("pre-fetching users");
 		my @Users =3D $db->getUsers($db->listUsers);
 		my %Users;
 		foreach my $User (@Users) {
@@ -80,7 +79,7 @@
=20
 			keys %Users;
 		#my @userInfo =3D (\%Users, \@sortedUserIDs);
-		$WeBWorK::timer->continue("done pre-fetching users") if defined($WeBWo=
rK::timer);
+		debug("done pre-fetching users");
 	=09
 		my $scoringType            =3D ($recordSingleSetScores) ?'everything':=
'totals';
 		my (@everything, @normal,@full,@info,@totalsColumn);
@@ -114,13 +113,9 @@
 	}=20
 =09
 	# Obtaining list of sets:
-	#$WeBWorK::timer->continue("Begin listing sets") if defined $WeBWorK::t=
imer;
 	my @setNames =3D  $db->listGlobalSets();
-	#$WeBWorK::timer->continue("End listing sets") if defined $WeBWorK::tim=
er;
 	my @set_records =3D ();
-	#$WeBWorK::timer->continue("Begin obtaining sets") if defined $WeBWorK:=
:timer;
 	@set_records =3D $db->getGlobalSets( @setNames);=20
-	#$WeBWorK::timer->continue("End obtaining sets: ".@set_records) if defi=
ned $WeBWorK::timer;
 =09
 =09
 	# store data
@@ -275,7 +270,6 @@
 	die "global set $setID not found. " unless $setRecord;
 	#my %users;
 	#my %userStudentID=3D();
-	#$WeBWorK::timer->continue("Begin getting users for set $setID") if def=
ined($WeBWorK::timer);
 	#foreach my $userID ($db->listUsers()) {
 	#	my $userRecord =3D $db->getUser($userID); # checked
 	#	die "user record for $userID not found" unless $userID;
@@ -285,7 +279,6 @@
 	#	$users{$userRecord->student_id} =3D $userRecord;
 	#	$userStudentID{$userID} =3D $userRecord->student_id;
 	#}
-	#$WeBWorK::timer->continue("End getting users for set $setID") if defin=
ed($WeBWorK::timer);=09
 =09
 	my %Users =3D %$UsersRef; # user objects hashed on user ID
 	my @sortedUserIDs =3D @$sortedUserIDsRef; # user IDs sorted by student =
ID
@@ -372,13 +365,13 @@
 	return @scoringData if $format eq "info";
 =09
 	# pre-fetch global problems
-	$WeBWorK::timer->continue("pre-fetching global problems for set $setID"=
) if defined($WeBWorK::timer);
+	debug("pre-fetching global problems for set $setID");
 	my %GlobalProblems =3D map { $_->problem_id =3D> $_ }
 		$db->getAllGlobalProblems($setID);
-	$WeBWorK::timer->continue("done pre-fetching global problems for set $s=
etID") if defined($WeBWorK::timer);
+	debug("done pre-fetching global problems for set $setID");
 =09
 	# pre-fetch user problems
-	$WeBWorK::timer->continue("pre-fetching user problems for set $setID") =
if defined($WeBWorK::timer);
+	debug("pre-fetching user problems for set $setID");
 	my %UserProblems; # $UserProblems{$userID}{$problemID}
=20
   # Gateway change here: for non-gateway (non-versioned) sets, we just g=
et each user's
@@ -415,7 +408,7 @@
 			$UserProblems{$userID} =3D \%CurrUserProblems;
 		}
 	}
-	$WeBWorK::timer->continue("done pre-fetching user problems for set $set=
ID") if defined($WeBWorK::timer);
+	debug("done pre-fetching user problems for set $setID");
 =09
 	# Write the problem data
 	my $dueDateString =3D $self->formatDateTime($setRecord->due_date);
@@ -520,7 +513,7 @@
=20
 		}
 	}
-	$WeBWorK::timer->continue("End  set $setID") if defined($WeBWorK::timer=
);
+	debug("End  set $setID");
 	return @scoringData;
 }
=20
Index: StudentProgress.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Instr=
uctor/StudentProgress.pm,v
retrieving revision 1.17
retrieving revision 1.18
diff -Llib/WeBWorK/ContentGenerator/Instructor/StudentProgress.pm -Llib/W=
eBWorK/ContentGenerator/Instructor/StudentProgress.pm -u -r1.17 -r1.18
--- lib/WeBWorK/ContentGenerator/Instructor/StudentProgress.pm
+++ lib/WeBWorK/ContentGenerator/Instructor/StudentProgress.pm
@@ -26,9 +26,10 @@
 use strict;
 use warnings;
 use CGI qw();
-use WeBWorK::Utils qw(readDirectory list2hash max sortByName);
-use WeBWorK::DB::Record::Set;
+use WeBWorK::Debug;
 use WeBWorK::ContentGenerator::Grades;
+use WeBWorK::DB::Record::Set;
+use WeBWorK::Utils qw(readDirectory list2hash max sortByName);
 use WeBWorK::Utils::SortRecords qw/sortRecords/;
=20
=20
@@ -350,10 +351,10 @@
 =09
 	my $max_num_problems  =3D 0;
 	# get user records
-	$WeBWorK::timer->continue("Begin obtaining user records for set $setNam=
e") if defined($WeBWorK::timer);
+	debug("Begin obtaining user records for set $setName");
 	my @userRecords  =3D $db->getUsers(@studentList);
-	$WeBWorK::timer->continue("End obtaining user records for set $setName"=
) if defined($WeBWorK::timer);
-    $WeBWorK::timer->continue("begin main loop") if defined($WeBWorK::ti=
mer);
+	debug("End obtaining user records for set $setName");
+    debug("begin main loop");
  	my @augmentedUserRecords    =3D ();
  	my $number_of_active_students;
=20
@@ -417,10 +418,10 @@
 		my %h_problemData   =3D ();
 		my $probNum         =3D 0;
 	=09
-		$WeBWorK::timer->continue("Begin obtaining problem records for user $s=
tudent set $setName") if defined($WeBWorK::timer);
+		debug("Begin obtaining problem records for user $student set $setName"=
);
 	=09
 		my @problemRecords =3D sort {$a->problem_id <=3D> $b->problem_id } $db=
->getAllUserProblems( $student, $sN );
-		$WeBWorK::timer->continue("End obtaining problem records for user $stu=
dent set $setName") if defined($WeBWorK::timer);
+		debug("End obtaining problem records for user $student set $setName");
 		my $num_of_problems =3D @problemRecords;
 		$max_num_problems =3D ($max_num_problems>=3D $num_of_problems) ? $max_=
num_problems : $num_of_problems;
 	   ########################################
@@ -628,7 +629,7 @@
=20
         } # this closes the loop through all student records
 =09
-	$WeBWorK::timer->continue("end mainloop") if defined($WeBWorK::timer);
+	debug("end mainloop");
 =09
 	@augmentedUserRecords =3D sort {
 		&$sort_method($a,$b,$primary_sort_method_name)
Index: SetsAssignedToUser.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Instr=
uctor/SetsAssignedToUser.pm,v
retrieving revision 1.20
retrieving revision 1.21
diff -Llib/WeBWorK/ContentGenerator/Instructor/SetsAssignedToUser.pm -Lli=
b/WeBWorK/ContentGenerator/Instructor/SetsAssignedToUser.pm -u -r1.20 -r1=
.21
--- lib/WeBWorK/ContentGenerator/Instructor/SetsAssignedToUser.pm
+++ lib/WeBWorK/ContentGenerator/Instructor/SetsAssignedToUser.pm
@@ -27,6 +27,7 @@
 use strict;
 use warnings;
 use CGI qw();
+use WeBWorK::Debug;
=20
 sub initialize {
 	my ($self)     =3D @_;
@@ -49,9 +50,9 @@
 =09
 	if (defined $r->param("assignToAll")) {
 		$self->assignAllSetsToUser($userID);
-		$WeBWorK::timer->continue("assignAllSetsToUser($userID)") if defined $=
WeBWorK::timer;
+		debug("assignAllSetsToUser($userID)");
 		$self->addmessage(CGI::div({class=3D>'ResultsWithoutError'}, "User has=
 been assigned to all current sets."));
-		$WeBWorK::timer->continue("done assignAllSetsToUsers($userID)") if def=
ined $WeBWorK::timer;
+		debug("done assignAllSetsToUsers($userID)");
 	} elsif (defined $r->param('unassignFromAll') and defined($r->param('un=
assignFromAllSafety')) and $r->param('unassignFromAllSafety')=3D=3D1) {
 		if ($userID ne $globalUserID) {
 		  $self->addmessage(CGI::div({class=3D>'ResultsWithoutError'}, "User h=
as been unassigned from all sets."));
@@ -79,9 +80,9 @@
 				# does the user want it to be assigned to the selected user
 				if (exists $selectedSets{$setID}) {
 					unless ($userSets{$setID}) {	# skip users already in the set
-						$WeBWorK::timer->continue("assignSetToUser($userID, $setID)") if d=
efined $WeBWorK::timer;
+						debug("assignSetToUser($userID, $setID)");
 						$self->assignSetToUser($userID, $setRecord);
-						$WeBWorK::timer->continue("done assignSetToUser($userID, $setID)")=
 if defined $WeBWorK::timer;
+						debug("done assignSetToUser($userID, $setID)");
 					}
 				} else {
 					# user asked to NOT have the set assigned to the selected user
Index: ProblemSetList.pm
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
RCS file: /webwork/cvs/system/webwork2/lib/WeBWorK/ContentGenerator/Instr=
uctor/ProblemSetList.pm,v
retrieving revision 1.83
retrieving revision 1.84
diff -Llib/WeBWorK/ContentGenerator/Instruc...
 
[truncated message content]