Log progress by time instead of count

Instead of logging the current file name every 1000 files we now log it
every 10 seconds. This makes it easier to see where backup is slow.

lib/Simba/CA.pm

@@ -232,9 +232,10 @@ sub backup2disk {
     $list_cfd->printflush("list $target->{dir}\n");	# XXX - encode!
     close($list_cfd);
     my $count = 0;
+    my $last_report = $self->{start_time};
     while (<$list_dfd>) {
-        if ($target->{timeout}) {
         my $now = time();
+        if ($target->{timeout}) {
             my $elapsed = $now - $self->{start_time};
             $self->log(10, "checking timeout " . $elapsed . " > " . $target->{timeout});
             if ($elapsed > $target->{timeout}) {
@@ -248,8 +249,9 @@ sub backup2disk {
 	# split into fields
         chomp;
 	my $f = $self->parse($_);
-        if ($count % 1000 == 0) {
+        if ($now - $last_report >= 10) {
             $self->log(9, "file $count: $f->{name}");
+            $last_report = $now;
         }
 
         my $success = 1;
@@ -543,6 +545,14 @@ sub db_record_version {
     my $t2b = gettimeofday();
     $self->{times}{db_record_version_versions2_get_version_id} += $t2b - $t2a;
     unless ($version_id) {
+        # We use a 32 bit int field in the database, so we have to clamp the mtime to that range.
+        # Need to fix this sometime before 2038 :-)
+        if ($f->{m} < -2147483648) {
+            $f->{m} = -2147483648;
+        } elsif ($f->{m} > 2147483647) {
+            $f->{m} = 2147483647;
+        }
+        $self->log(10, "insert into versions2(..., file_mtime=$f->{m}, ...)");
         # XXX why is $f->{checksum} undef here for ./bin/dash?
         $self->{dbh}->do("insert into versions2(
                                                 file_type, file_size, file_mtime,
@@ -566,6 +576,7 @@ sub db_record_version {
                          $f->{checksum}, $f->{lt},
                         );
         $version_id = $self->{dbh}->{mysql_insertid};
+        $self->log(10, "insert into versions2 -> $version_id");
     }
     my $t3 = gettimeofday();
     $self->{times}{db_record_version_versions2} += $t3 - $t2;

scripts/graph_free

@@ -0,0 +1,22 @@
+#!/usr/bin/perl 
+use v5.24;
+use warnings;
+
+open my $tsfh, '>', "graph_free.tsv";
+for my $fn (glob("/var/log/simba/ca.*")) {
+    my $fh;
+    if ($fn =~ /\.gz$/) {
+        open($fh, '-|', "zcat", $fn);
+    } else {
+        open ($fh, '<', $fn);
+    }
+    while (<$fh>) {
+        if (m{(....-..-..T..:..:..[-+]....) .*: found base /backup/(.*) \(est. (\d+) bytes\)}) {
+            say $tsfh "$1\t$2\t$3"
+        }
+    }
+}
+close $tsfh;
+
+open STDOUT, '>', "graph_free.png";
+system "tsplotv", "--style", "points", "--legend-position", "below", "--yrange", "0:*", "graph_free.tsv";

scripts/graph_used

@@ -0,0 +1,20 @@
+#!/usr/bin/perl 
+use v5.24;
+use warnings;
+
+open my $tsfh, '>', "graph_used.tsv";
+for my $fn (glob("/var/log/simba/ca.*")) {
+    open (my $fh, '<', $fn);
+    my %free;
+    while (<$fh>) {
+        if (m{(....-..-..T..:..:..[-+]....) .*: considering base /backup/(.*) \(est. (\d+) bytes\)}) {
+            $free{$2} = $3;
+        } elsif (m{(....-..-..T..:..:..[-+]....) .*: using base /backup/(.*)}) {
+            say $tsfh "$1\t$2\t$free{$2}"
+        }
+    }
+}
+close $tsfh;
+
+open STDOUT, '>', "graph_used.png";
+system "tsplotv", "--style", "points", "--legend-position", "below", "graph_used.tsv";