SciTE console shows elapsed time in scientific format for long run times - console output issues

[Confuzzled]

Scenario: Running a long process to delete emails programmatically in a loop by accessing the Outlook object using OutlookEX UDF invoked from SciTE-Lite Version 3.5.4 on Windows 10 machine.

Console output shown below. Please note the scientific notation for the time elapsed.

+>19:39:43 Starting AutoIt3Wrapper v.2.0.0.3    Environment(Language:0409  Keyboard:00000409  OS:WIN_VISTA/  CPU:X64 OS:X86)
>Running AU3Check (3.3.15.0)  from:C:\Program Files\AutoIt3
+>19:39:44 AU3Check ended.rc:0
>Running:(3.3.15.0):C:\Program Files\AutoIt3\autoit3.exe....

<<console output for long job - many lines, and all correctly processed>>

***Finished***

+>23:17:23 AutoIT3.exe ended.rc:0
+>23:17:24 AutoIt3Wrapper Finished
>Exit code: 0    Time: 1.306e+004

A shorter job that takes about half a minutes displays the following:

>Exit code: 0    Time: 31.67

1. Would appreciate elapsed time in seconds, minutes, hours, days, etc as integer or decimal, rather than scientific format. Is the variable too short to fit the values?

2. Could we also put the unit that is being displayed, eg seconds, minutes, hours, days etc that elapsed?

3. Could we have a space just prior to the rc=0, and after Language:0409, and after Keyboard:000 colons please? (see AutoIT3Wrapper first line output)

[Jos]

1 hour ago, Confuzzled said:

1. Would appreciate elapsed time in seconds, minutes, hours, days, etc as integer or decimal, rather than scientific format. Is the variable too short to fit the values?

2. Could we also put the unit that is being displayed, eg seconds, minutes, hours, days etc that elapsed?

3. Could we have a space just prior to the rc=0, and after Language:0409, and after Keyboard:000 colons please? (see AutoIT3Wrapper first line output)

Any mayo or ketchup with that?  

1&2: This comes from SciTE and is part of the standard SciTE package.

>Exit code: 0    Time: 31.67

The other suggestion is part of AutoIt3Wrapper and simple to change.

Edited May 25, 2022 by Jos

[Confuzzled]

Thanks, I'll report the first two there. The third is when you are there in the code, you may as well do it.

Mayo is fattening - no coffee for you! 🙂

[Jos]

59 minutes ago, Jos said:

3. Could we have a space just prior to the rc=0, and after Language:0409, and after Keyboard:000 colons please? (see AutoIT3Wrapper first line output)

• I have added a space before rc:0 in any standard lines like these: 

  • AU3Check ended. rc:0

  • AutoIT3 ended. rc:0

• I won't be changing any spacing around the colons in RC:0 Language:0409 Keyboard:000

Jos 

Edited May 25, 2022 by Jos

[Confuzzled]

Had a peek at the source code of Scintilla release 5.2.3 in the ElapsedPeriod.h module:

// Scintilla source code edit control
/** @file ElapsedPeriod.h
 ** Encapsulate C++ <chrono> to simplify use.
 **/
// Copyright 2018 by Neil Hodgson <neilh@scintilla.org>
// The License.txt file describes the conditions under which this software may be distributed.

#ifndef ELAPSEDPERIOD_H
#define ELAPSEDPERIOD_H

namespace Scintilla::Internal {

// Simplified access to high precision timing.
class ElapsedPeriod {
    using ElapsedClock = std::chrono::steady_clock;
    ElapsedClock::time_point tp;
public:
    /// Capture the moment
    ElapsedPeriod() noexcept : tp(ElapsedClock::now()) {
    }
    /// Return duration as floating point seconds
    double Duration(bool reset=false) noexcept {
        const ElapsedClock::time_point tpNow = ElapsedClock::now();
        const std::chrono::duration<double> duration =
            std::chrono::duration_cast<std::chrono::duration<double>>(tpNow - tp);
        if (reset) {
            tp = tpNow;
        }
        return duration.count();
    }
};

}

#endif

Double?

[Confuzzled]

catch.hpp module - lines 2053 to 2146 seem to be relevant...  version 2.13.7 from Two Blue Cubes Ltd

expandcollapse popup

// Separate std::chrono::duration specialization
#if defined(CATCH_CONFIG_ENABLE_CHRONO_STRINGMAKER)
#include <ctime>
#include <ratio>
#include <chrono>

namespace Catch {

template <class Ratio>
struct ratio_string {
    static std::string symbol();
};

template <class Ratio>
std::string ratio_string<Ratio>::symbol() {
    Catch::ReusableStringStream rss;
    rss << '[' << Ratio::num << '/'
        << Ratio::den << ']';
    return rss.str();
}
template <>
struct ratio_string<std::atto> {
    static std::string symbol();
};
template <>
struct ratio_string<std::femto> {
    static std::string symbol();
};
template <>
struct ratio_string<std::pico> {
    static std::string symbol();
};
template <>
struct ratio_string<std::nano> {
    static std::string symbol();
};
template <>
struct ratio_string<std::micro> {
    static std::string symbol();
};
template <>
struct ratio_string<std::milli> {
    static std::string symbol();
};

    ////////////
    // std::chrono::duration specializations
    template<typename Value, typename Ratio>
    struct StringMaker<std::chrono::duration<Value, Ratio>> {
        static std::string convert(std::chrono::duration<Value, Ratio> const& duration) {
            ReusableStringStream rss;
            rss << duration.count() << ' ' << ratio_string<Ratio>::symbol() << 's';
            return rss.str();
        }
    };
    template<typename Value>
    struct StringMaker<std::chrono::duration<Value, std::ratio<1>>> {
        static std::string convert(std::chrono::duration<Value, std::ratio<1>> const& duration) {
            ReusableStringStream rss;
            rss << duration.count() << " s";
            return rss.str();
        }
    };
    template<typename Value>
    struct StringMaker<std::chrono::duration<Value, std::ratio<60>>> {
        static std::string convert(std::chrono::duration<Value, std::ratio<60>> const& duration) {
            ReusableStringStream rss;
            rss << duration.count() << " m";
            return rss.str();
        }
    };
    template<typename Value>
    struct StringMaker<std::chrono::duration<Value, std::ratio<3600>>> {
        static std::string convert(std::chrono::duration<Value, std::ratio<3600>> const& duration) {
            ReusableStringStream rss;
            rss << duration.count() << " h";
            return rss.str();
        }
    };

    ////////////
    // std::chrono::time_point specialization
    // Generic time_point cannot be specialized, only std::chrono::time_point<system_clock>
    template<typename Clock, typename Duration>
    struct StringMaker<std::chrono::time_point<Clock, Duration>> {
        static std::string convert(std::chrono::time_point<Clock, Duration> const& time_point) {
            return ::Catch::Detail::stringify(time_point.time_since_epoch()) + " since epoch";
        }
    };
    // std::chrono::time_point<system_clock> specialization
    template<typename Duration>
    struct StringMaker<std::chrono::time_point<std::chrono::system_clock, Duration>> {
        static std::string convert(std::chrono::time_point<std::chrono::system_clock, Duration> const& time_point) {
            auto converted = std::chrono::system_clock::to_time_t(time_point);

 

Edited May 25, 2022 by Confuzzled

[Jos]

Nah ....  Think it should be changed in the SciTE code in SciTEWin.cxx:

stExitMessage << ">Exit code: " << exitcode;
        if (jobQueue.TimeCommands()) {
            stExitMessage << "    Time: ";
            stExitMessage << std::setprecision(4) << cmdWorker.commandTime.Duration();
        }

... but I am not going to make changes in my version for this as I assume 99.99% of the usage of SciTE this isn't applicable plus it is really only "cosmetic".  
Maybe Neil is interested to change this in the Core version which I use when I update out version.  

Edited May 25, 2022 by Jos

[Musashi]

6 hours ago, Confuzzled said:

Scenario: Running a long process to delete emails programmatically in a loop ... Console output shown below. Please note the scientific notation for the time elapsed.

>Exit code: 0    Time: 1.306e+004

Just out of curiosity : Wouldn't it be far easier and less invasive to use AutoIt's internal functions for time measurement ?

Example :

#include <Timers.au3>
HotKeySet("{ESC}", _Terminate) ; just to terminate this example
OnAutoItExitRegister("_MyExitFunc")
Local $hStarttime = _Timer_Init()

; do something
While True
    Sleep(50)
WEnd

Func _MyExitFunc()
    ConsoleWrite("Time elapsed = " & _Timer_Diff($hStarttime) & @CRLF)
EndFunc   ;==>_MyExitFunc

Func _Terminate()
    Exit
EndFunc   ;==>_Terminate

 

[Confuzzled]

Musashi: Of course I could add this elapsed timer to my code as a wrapper, but it is the console where the aberration is happening. I like to have the problem solved once and for all rather than implement workarounds globally. Do you unwind the workarounds once the problem gets fixed? Yikes - imagine all the releases, version control activity, and associated support issues for each bit of code.

I have absolute trust in Jos to make the tweaks as time permits. Knowing most programmers, they absolutely hate to do a new release with known (minor) issues!

Edited May 26, 2022 by Confuzzled

[Jos]

2 hours ago, Confuzzled said:

I have absolute trust in Jos to make the tweaks as time permits.

As stated: I won't be making this (rather easy) change myself in the SciTE4AutoIt3 version unless it is made in the official version published by Neil Hodgson, which I use to apply my changes specifically for AutoIt3. 

I doubt many people will be running scripts from SciTE that take longer than a day as to me SciTE is used to develop scripts and not to run them for a long period.  

Edited May 26, 2022 by Jos

[Confuzzled]

It wasn't even four hours - just "1.306e+004" and I think it is seconds, based on the second part of my first post. The point is it should be shown, and be understandable.

Scientific notation is for scientists, not coders!

[Jos]

So what did Neil say when you asked? 

[Confuzzled]

On 6/8/2022 at 11:36 PM, Jos said:

So what did Neil say when you asked? 

He asked to report it to the mailing list as a feature request, or write a wrapper around it (as Musashi suggested)

Sorry to have wasted everybody's time (pun intended) - I will just write shorter code in the future.

Edited June 13, 2022 by Confuzzled

[Jos]

1 hour ago, Confuzzled said:

He asked to report it to the mailing list as a feature request

This could be a "The luxe option" with this change in SciTEWin.cxx:

		::GetExitCodeProcess(pi.hProcess, &exitcode);
		std::ostringstream stExitMessage;
		stExitMessage << ">Exit code: " << exitcode;
		if (jobQueue.TimeCommands()) {
			stExitMessage << "    Time: ";
			//+++ Start Update +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
			//Old: stExitMessage << std::setprecision(4) << cmdWorker.commandTime.Duration();
			// New code 
			double Duration = cmdWorker.commandTime.Duration();
			// Below 1 minute   : 59.9 seconds
			// Longer than 1 min: 23:59:59.9
			// Longer than 1 day: 99 days 11:22:33.4
			char sDuration[20];	
			// convert seconds into hr, min, sec
			int days = (int)((int)Duration / (3600 * 24));
			int hr = ((int)((int)Duration % (3600 * 24))) / 3600;;
			int min = ((int)((int)Duration % 3600)) / 60;
			double sec = Duration - (days * 3600 * 243) - (hr * 3600) - (min * 60);
			if (days > 0)
				stExitMessage << days << " days, ";
			if (hr > 0 || min > 0) {
				sprintf(sDuration, "%02d:%02d:%04.1f", hr, min, sec);
			} else {
				sprintf(sDuration, "%4.1f seconds", sec);
			}
			stExitMessage << sDuration;
			//=+= End Update ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
		}
		stExitMessage << "\n";
		OutputAppendStringSynchronised(stExitMessage.str().c_str());

 

[mLipok]

On 6/8/2022 at 10:21 AM, Confuzzled said:

just "1.306e+004" and I think it is seconds

Is it micro seconds ?

[Confuzzled]

I was running it on a Windows 10 machine, not a quantum computer!

You have just proved my point - nobody knows the units, as they are not mentioned, and not in a understandable format.

[argumentum]

57 minutes ago, Confuzzled said:

nobody knows the units, as they are not mentioned

.. is in seconds. But this is AutoIt and the time the editor say it was running is quite meaningless for fraction of seconds. Use a timer ( as @Musashi posted above ) if that measurement has importance. But I do agree that a scientific notation can mess with one's visual Feng Shui  

Edit: This is my take at a timer thing: 

OnAutoItExitRegister("_MyExitFunc")
Global $g___hStarttime = TimerInit()
Func _MyExitFunc()
    ConsoleWrite(@CRLF & "- Time elapsed = " & TimeTimerDiff( TimerDiff($g___hStarttime) ) & @CRLF & @CRLF)
EndFunc   ;==>_MyExitFunc
Func TimeTimerDiff($ms)
    Local $day, $iHours, $iMins, $iSecs, $iTicks = $ms, $sMsOut = $ms
    $iTicks = Int($iTicks / 1000)
    $iHours = Int($iTicks / 3600)
    $iTicks = Mod($iTicks, 3600)
    $iMins = Int($iTicks / 60)
    $iSecs = Mod($iTicks, 60)
    If $iHours > 23 Then
        $day = $iHours / 24
        $iHours = Mod($iHours, 24)
    EndIf
    $ms = "0000" & $ms
    Return $sMsOut & @TAB & StringReplace(StringFormat("%03i %02i:%02i:%02i", $day, $iHours, $iMins, $iSecs), "000 ", "") & '.' & StringReplace(StringTrimLeft($ms, StringInStr($ms, ".") - 4), ".", ",")
EndFunc   ;==>TimeTimerDiff
;~ Sleep(1)
Exit

I find this clear and readable.

Edited June 16, 2022 by argumentum
nicer looking

[Confuzzled]

I'm going to sincerely thank you for your effort to post added 22 lines of code to bypass an easily fixable issue. The entire AutoIT cohort is welcome to add the code as a wrapper to 'fix' the issue.

See any issues with that statement?

Looks like Neil and Jos are already on the correct solution. I await the new version with the simple fix rolled out.

[Jos]

1 hour ago, Confuzzled said:

Looks like Neil and Jos are already on the correct solution.

Do you have a link for the request you made? I don't see it in the SciTE-Interest maillist or Sourceforge.net.