a better rough idea of where freeside-upgrade spends time

diff --git a/FS/FS/Upgrade.pm b/FS/FS/Upgrade.pm
index f10ff06..97f24d4 100644 (file)
--- a/FS/FS/Upgrade.pm
+++ b/FS/FS/Upgrade.pm
@@ -51,6 +51,8 @@ sub upgrade {
     if ( $class->can('_upgrade_data') ) {
       warn "Upgrading $table...\n";
 
+      my $start = time;
+
       my $oldAutoCommit = $FS::UID::AutoCommit;
       local $FS::UID::AutoCommit = 0;
       $FS::UID::AutoCommit = 0;
@@ -60,6 +62,9 @@ sub upgrade {
       if ( $oldAutoCommit ) {
         dbh->commit or die dbh->errstr;
       }
+      
+      #warn "\e[1K\rUpgrading $table... done in ". (time-$start). " seconds\n";
+      warn "  done in ". (time-$start). " seconds\n";
 
     } else {
       warn "WARNING: asked for upgrade of $table,".

diff --git a/FS/bin/freeside-upgrade b/FS/bin/freeside-upgrade
index 0b5758d..c988e13 100755 (executable)
--- a/FS/bin/freeside-upgrade
+++ b/FS/bin/freeside-upgrade
@@ -13,6 +13,8 @@ use FS::Conf;
 use FS::Record qw(qsearch);
 use FS::Upgrade qw(upgrade upgrade_sqlradius);
 
+my $start = time;
+
 die "Not running uid freeside!" unless checkeuid();
 
 getopts("dqs");
@@ -36,6 +38,9 @@ dbdef_create($dbh, $dbdef_file);
 delete $FS::Schema::dbdef_cache{$dbdef_file}; #force an actual reload
 reload_dbdef($dbdef_file);
 
+warn "Upgrade startup completed in ". (time-$start). " seconds\n"; # if $DEBUG;
+$start = time;
+
 $DBIx::DBSchema::DEBUG = $DEBUG;
 $DBIx::DBSchema::Table::DEBUG = $DEBUG;
 $DBIx::DBSchema::Index::DEBUG = $DEBUG;
@@ -65,14 +70,23 @@ if ( $DRY_RUN ) {
       or die "Error: ". $dbh->errstr. "\n executing: $statement";
   }
 
+  warn "Pre-schema change upgrades completed in ". (time-$start). " seconds\n"; # if $DEBUG;
+  $start = time;
+
   dbdef->update_schema( dbdef_dist(datasrc), $dbh );
 }
 
+warn "Schema upgrade completed in ". (time-$start). " seconds\n"; # if $DEBUG;
+$start = time;
+
 my $hashref = {};
 $hashref->{dry_run} = 1 if $DRY_RUN;
 $hashref->{debug} = 1 if $DEBUG && $DRY_RUN;
 prune_applications($hashref) unless $opt_s;
 
+warn "Application pruning completed in ". (time-$start). " seconds\n"; # if $DEBUG;
+$start = time;
+
 print "\n" if $DRY_RUN;
 
 if ( $dbh->{Driver}->{Name} =~ /^mysql/i && ! $opt_s ) {
@@ -97,6 +111,9 @@ if ( $dbh->{Driver}->{Name} =~ /^mysql/i && ! $opt_s ) {
 
   }
 
+  warn "Duplication lock creation completed in ". (time-$start). " seconds\n"; # if $DEBUG;
+  $start = time;
+
 }
 
 $dbh->commit or die $dbh->errstr;
@@ -126,15 +143,26 @@ $dbh->disconnect or die $dbh->errstr;
 
 $dbh = adminsuidsetup($user);
 
+warn "Re-initialization with updated schema completed in ". (time-$start). " seconds\n"; # if $DEBUG;
+$start = time;
+
 upgrade()
   unless $DRY_RUN || $opt_s;
 
+warn "Table updates completed in ". (time-$start). " seconds\n"; # if $DEBUG;
+$start = time;
+
 upgrade_sqlradius()
   unless $DRY_RUN || $opt_s;
 
+warn "SQL RADIUS updates completed in ". (time-$start). " seconds\n"; # if $DEBUG;
+$start = time;
+
 $dbh->commit or die $dbh->errstr;
 $dbh->disconnect or die $dbh->errstr;
 
+warn "Commit and disconnection completed in ". (time-$start). " seconds; upgrade done!\n"; # if $DEBUG;
+
 ###
 
 sub dbdef_create { # reverse engineer the schema from the DB and save to file