Incorrect measurement of migration duration in case of execution several expressions

[OlegUfaev]

We have migration via Fluent API

[Migration(20230629130000, "Add column APPLIED_COUNT in PASSPORT")]
public class AddAppliedCountColumnInPassport : ForwardOnlyMigration
{
    public override void Up()
    {
        Alter.Table("PASSPORT")
            .AddColumn("APPLIED_COUNT")
            .AsInt32()
            .SetExistingRowsTo(0)
            .WithDefaultValue(0)
            .NotNullable();
    }
}

After performing this migration on our database, we looked at the logs and saw that the overall migration execution time is incorrect. The total migration execution time is about 23 minutes (as you can see from the timestamps in the log or the sum of the durations of the individual commands: 1150+230=1380sec/60=23min), and in the last FluentMigrator record we saw that the duration is barely over the execution time of the last command from the migration.

[15:11:03] : 20230629130000: AddAppliedCountColumnInPassport migrating
[15:11:03] : -------------------------------------------------------------------------------
[15:11:03] : Beginning Transaction
[15:11:03] : AlterTable PASSPORT
[15:11:03] : No SQL statement executed.
[15:11:03] : => 0.0005738s
[15:11:03] : CreateColumn PASSPORT APPLIED_COUNT Int32
[15:11:03] : ALTER TABLE PASSPORT ADD APPLIED_COUNT NUMBER(10,0) DEFAULT 0
[15:11:04] : => 0.8750637s
[15:11:04] : UpdateData 
[15:11:04] : UPDATE PASSPORT SET APPLIED_COUNT = 0 WHERE 1 = 1
[15:30:15] : => 1150.292614s
[15:30:15] : AlterColumn PASSPORT APPLIED_COUNT Int32
[15:30:15] : ALTER TABLE PASSPORT MODIFY APPLIED_COUNT NUMBER(10,0) DEFAULT 0 NOT NULL
[15:34:05] : => 230.3295301s
[15:34:05] : INSERT ALL INTO VersionInfo (Version, AppliedOn, Description) VALUES (20230629130000, to_date('2023-06-30 10:34:05', 'yyyy-mm-dd hh24:mi:ss'), 'Add column APPLIED_COUNT in PASSPORT.') SELECT 1 FROM DUAL
[15:34:05] : Committing Transaction
[15:34:05] : 20230629130000: AddAppliedCountColumnInPassport migrated
[15:34:05] : => 230.3913764s

Expected behavior
The last log entry for this migration shows the total execution time for the entire migration.

Information (please complete the following information):

• OS: Windows 10 Pro
• Platform: [.NET Framework 4.x / .NET Core 2.x , etc]
• FluentMigrator version: 3.3.2
• FluentMigrator runner: "in-process runner"
• Database Management System: [Oracle]
• Database Management System Version: "Oracle 19c"

Additional context
The problem seems to be that you are using the same StopWatch instance in MigrationRunner.cs to measure the execution time of both the entire migration and individual expressions. Thus, the duration of the entire migration is defined as the duration of the last expression + a small quantum of time before the final call to the _stopwatch.Stop() method.

[jzabroski]

It should use a PerformanceLogger abstraction that implements IDisposable.

Do you want to submit a PR?

[OlegUfaev]

While the problem looks pretty simple, unfortunately, I don't know the FluentMigrator code well enough to suggest a specific fix.

[jzabroski]

@OlegUfaev Can you show me the second migration here? I dont think I have enough information to reproduce the problem without a lot of unnecessary guesswork.

[jzabroski]

Wait, nevermind, late night coding - I see it now.

[jzabroski]

It seems that the way it does this in 'one step' is to create a separate migration expression behind the scenes. Next steps are to figure out why it does not bubble up with the right timing.

fluentmigrator/src/FluentMigrator/Builders/ColumnExpressionBuilderHelper.cs

Lines 119 to 155 in 4327993

	public virtual void SetExistingRowsTo(object existingRowValue)
	{
	//TODO: validate that 'value' isn't set to null for non nullable columns. If set to
	//null, maybe just remove the expressions?.. not sure of best way to handle this.
	var column = _builder.Column;
	if (column.ModificationType == ColumnModificationType.Create)
	{
	//ensure an UpdateDataExpression is created and cached for this column
	ExistingRowsData exRowExpr;
	if (!_existingRowsDataByColumn.TryGetValue(column, out exRowExpr))
	{
	exRowExpr = new ExistingRowsData();
	_existingRowsDataByColumn.Add(column, exRowExpr);
	}
	if (exRowExpr.SetExistingRowsExpression == null)
	{
	exRowExpr.SetExistingRowsExpression = new UpdateDataExpression
	{
	TableName = _builder.TableName,
	SchemaName = _builder.SchemaName,
	IsAllRows = true,
	};
	_context.Expressions.Add(exRowExpr.SetExistingRowsExpression);
	//Call SetNullable, to ensure that not-null columns are correctly set to
	//not null after existing rows have data populated.
	SetNullable(column.IsNullable ?? true);
	}
	exRowExpr.SetExistingRowsExpression.Set = new List<KeyValuePair<string, object>> {
	new KeyValuePair<string, object>(column.Name, existingRowValue)
	};
	}
	}