accounting: fix total duration calculation

This was broken in e337cae0c5 when we deleted the transfers
immediately.

This is fixed by keeping a merged slice of time ranges of completed
transfers and adding those to the current transfers.

fs/accounting/stats.go

@@ -34,7 +34,8 @@ type StatsInfo struct {
 	renameQueueSize   int64
 	deletes           int64
 	inProgress        *inProgress
-	startedTransfers  []*Transfer
+	startedTransfers  []*Transfer // currently active transfers
+	oldTimeRanges     timeRanges  // a merged list of time ranges for the transfers
 }
 
 // NewStats creates an initialised StatsInfo
@@ -109,50 +110,76 @@ func (s *StatsInfo) transferRemoteStats(name string) rc.Params {
 	return rc.Params{"name": name}
 }
 
+// timeRange is a start and end time of a transfer
 type timeRange struct {
 	start time.Time
 	end   time.Time
 }
 
+// timeRanges is a list of non-overlapping start and end times for
+// transfers
+type timeRanges []timeRange
+
+// merge all the overlapping time ranges
+func (trs *timeRanges) merge() {
+	Trs := *trs
+
+	// Sort by the starting time.
+	sort.Slice(Trs, func(i, j int) bool {
+		return Trs[i].start.Before(Trs[j].start)
+	})
+
+	// Merge overlaps and add distinctive ranges together
+	var (
+		newTrs = Trs[:0]
+		i, j   = 0, 1
+	)
+	for i < len(Trs) {
+		if j < len(Trs) {
+			if !Trs[i].end.Before(Trs[j].start) {
+				if Trs[i].end.Before(Trs[j].end) {
+					Trs[i].end = Trs[j].end
+				}
+				j++
+				continue
+			}
+		}
+		newTrs = append(newTrs, Trs[i])
+		i = j
+		j++
+	}
+
+	*trs = newTrs
+}
+
+// total the time out of the time ranges
+func (trs timeRanges) total() (total time.Duration) {
+	for _, tr := range trs {
+		total += tr.end.Sub(tr.start)
+	}
+	return total
+}
+
 // Total duration is union of durations of all transfers belonging to this
 // object.
 // Needs to be protected by mutex.
 func (s *StatsInfo) totalDuration() time.Duration {
-	now := time.Now()
+	// copy of s.oldTimeRanges with extra room for the current transfers
+	timeRanges := make(timeRanges, len(s.oldTimeRanges), len(s.oldTimeRanges)+len(s.startedTransfers))
+	copy(timeRanges, s.oldTimeRanges)
+
 	// Extract time ranges of all transfers.
-	timeRanges := make([]timeRange, len(s.startedTransfers))
+	now := time.Now()
 	for i := range s.startedTransfers {
 		start, end := s.startedTransfers[i].TimeRange()
 		if end.IsZero() {
 			end = now
 		}
-		timeRanges[i] = timeRange{start, end}
+		timeRanges = append(timeRanges, timeRange{start, end})
 	}
 
-	// Sort by the starting time.
+	timeRanges.merge()
-	sort.Slice(timeRanges, func(i, j int) bool {
+	return timeRanges.total()
-		return timeRanges[i].start.Before(timeRanges[j].start)
-	})
-
-	// Merge overlaps and add distinctive ranges together for total.
-	var total time.Duration
-	var i, j = 0, 1
-	for i < len(timeRanges) {
-		if j < len(timeRanges) {
-			if timeRanges[j].start.Before(timeRanges[i].end) {
-				if timeRanges[i].end.Before(timeRanges[j].end) {
-					timeRanges[i].end = timeRanges[j].end
-				}
-				j++
-				continue
-			}
-		}
-		total += timeRanges[i].end.Sub(timeRanges[i].start)
-		i = j
-		j++
-	}
-
-	return total
 }
 
 // eta returns the ETA of the current operation,
@@ -536,6 +563,15 @@ func (s *StatsInfo) AddTransfer(transfer *Transfer) {
 // RemoveTransfer removes a reference to the started transfer.
 func (s *StatsInfo) RemoveTransfer(transfer *Transfer) {
 	s.mu.Lock()
+
+	// add finished transfer onto old time ranges
+	start, end := transfer.TimeRange()
+	if end.IsZero() {
+		end = time.Now()
+	}
+	s.oldTimeRanges = append(s.oldTimeRanges, timeRange{start, end})
+	s.oldTimeRanges.merge()
+
 	for i, tr := range s.startedTransfers {
 		if tr == transfer {
 			// remove the found entry

fs/accounting/stats_test.go

@@ -9,6 +9,7 @@ import (
 	"github.com/pkg/errors"
 	"github.com/rclone/rclone/fs/fserrors"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 func TestETA(t *testing.T) {
@@ -138,52 +139,65 @@ func TestStatsTotalDuration(t *testing.T) {
 
 	t.Run("Single completed transfer", func(t *testing.T) {
 		s := NewStats()
-		s.AddTransfer(&Transfer{
+		tr1 := &Transfer{
 			startedAt:   time1,
 			completedAt: time2,
-		})
+		}
+		s.AddTransfer(tr1)
 
 		s.mu.Lock()
 		total := s.totalDuration()
 		s.mu.Unlock()
 
+		assert.Equal(t, 1, len(s.startedTransfers))
 		assert.Equal(t, 10*time.Second, total)
+		s.RemoveTransfer(tr1)
+		assert.Equal(t, 10*time.Second, total)
+		assert.Equal(t, 0, len(s.startedTransfers))
 	})
 
 	t.Run("Single uncompleted transfer", func(t *testing.T) {
 		s := NewStats()
-		s.AddTransfer(&Transfer{
+		tr1 := &Transfer{
 			startedAt: time1,
-		})
+		}
+		s.AddTransfer(tr1)
 
 		s.mu.Lock()
 		total := s.totalDuration()
 		s.mu.Unlock()
 
 		assert.Equal(t, time.Since(time1)/time.Second, total/time.Second)
+		s.RemoveTransfer(tr1)
+		assert.Equal(t, time.Since(time1)/time.Second, total/time.Second)
 	})
 
 	t.Run("Overlapping without ending", func(t *testing.T) {
 		s := NewStats()
-		s.AddTransfer(&Transfer{
+		tr1 := &Transfer{
 			startedAt:   time2,
 			completedAt: time3,
-		})
+		}
-		s.AddTransfer(&Transfer{
+		s.AddTransfer(tr1)
+		tr2 := &Transfer{
 			startedAt:   time2,
 			completedAt: time2.Add(time.Second),
-		})
+		}
-		s.AddTransfer(&Transfer{
+		s.AddTransfer(tr2)
+		tr3 := &Transfer{
 			startedAt:   time1,
 			completedAt: time3,
-		})
+		}
-		s.AddTransfer(&Transfer{
+		s.AddTransfer(tr3)
+		tr4 := &Transfer{
 			startedAt:   time3,
 			completedAt: time4,
-		})
+		}
-		s.AddTransfer(&Transfer{
+		s.AddTransfer(tr4)
+		tr5 := &Transfer{
 			startedAt: time.Now(),
-		})
+		}
+		s.AddTransfer(tr5)
 
 		time.Sleep(time.Millisecond)
 
@@ -192,6 +206,14 @@ func TestStatsTotalDuration(t *testing.T) {
 		s.mu.Unlock()
 
 		assert.Equal(t, time.Duration(30), total/time.Second)
+		s.RemoveTransfer(tr1)
+		assert.Equal(t, time.Duration(30), total/time.Second)
+		s.RemoveTransfer(tr2)
+		assert.Equal(t, time.Duration(30), total/time.Second)
+		s.RemoveTransfer(tr3)
+		assert.Equal(t, time.Duration(30), total/time.Second)
+		s.RemoveTransfer(tr4)
+		assert.Equal(t, time.Duration(30), total/time.Second)
 	})
 
 	t.Run("Mixed completed and uncompleted transfers", func(t *testing.T) {
@@ -217,3 +239,70 @@ func TestStatsTotalDuration(t *testing.T) {
 		assert.Equal(t, startTime.Sub(time1)/time.Second, total/time.Second)
 	})
 }
+
+// make time ranges from string description for testing
+func makeTimeRanges(t *testing.T, in []string) timeRanges {
+	trs := make(timeRanges, len(in))
+	for i, Range := range in {
+		var start, end int64
+		n, err := fmt.Sscanf(Range, "%d-%d", &start, &end)
+		require.NoError(t, err)
+		require.Equal(t, 2, n)
+		trs[i] = timeRange{time.Unix(start, 0), time.Unix(end, 0)}
+	}
+	return trs
+}
+
+func TestTimeRangeMerge(t *testing.T) {
+	for _, test := range []struct {
+		in   []string
+		want []string
+	}{{
+		in:   []string{},
+		want: []string{},
+	}, {
+		in:   []string{"1-2"},
+		want: []string{"1-2"},
+	}, {
+		in:   []string{"1-4", "2-3"},
+		want: []string{"1-4"},
+	}, {
+		in:   []string{"2-3", "1-4"},
+		want: []string{"1-4"},
+	}, {
+		in:   []string{"1-3", "2-4"},
+		want: []string{"1-4"},
+	}, {
+		in:   []string{"2-4", "1-3"},
+		want: []string{"1-4"},
+	}, {
+		in:   []string{"1-2", "2-3"},
+		want: []string{"1-3"},
+	}, {
+		in:   []string{"2-3", "1-2"},
+		want: []string{"1-3"},
+	}, {
+		in:   []string{"1-2", "3-4"},
+		want: []string{"1-2", "3-4"},
+	}, {
+		in:   []string{"1-3", "7-8", "4-6", "2-5", "7-8", "7-8"},
+		want: []string{"1-6", "7-8"},
+	}} {
+
+		in := makeTimeRanges(t, test.in)
+		in.merge()
+
+		got := []string{}
+		for _, tr := range in {
+			got = append(got, fmt.Sprintf("%d-%d", tr.start.Unix(), tr.end.Unix()))
+		}
+
+		assert.Equal(t, test.want, got)
+	}
+}
+
+func TestTimeRangeDuration(t *testing.T) {
+	assert.Equal(t, 0*time.Second, timeRanges{}.total())
+	assert.Equal(t, 1*time.Second, makeTimeRanges(t, []string{"1-2"}).total())
+	assert.Equal(t, 91*time.Second, makeTimeRanges(t, []string{"1-2", "10-100"}).total())
+}