Memory leak in "clock format"

[John Jester]

There seems to be a memory leak with the clock format command. I've tested this in freewrap 6.74 on Windows and tclsh 8.6 on Linux with the same result.

Using this code:

for { set i 0 } { $i < 1000 } { incr i } { clock format 0 -format [expr rand()] }

I see an increase in memory of about ~2 MB. Increasing the limit from 1,000 to 10,000 yields a memory increase of ~20 MB, so it seems linear at about 2 kB leaked per iteration. Same for 100,0000, with ~200 MB increase.

The reason I discovered this is I was trying to extend "clock format" to work with milli- and microseconds, so I was doing something like this:

clock format [clock microseconds] -format {%H:%M:%S.%us}
==>
clock format <seconds from above> -format {%H:%M:%S.123456}

which is how I ended up asking clock format to do a bunch of different formats in rapid succession.

[Rich]

John Jester <kuulg...@gmail.com> wrote:
> There seems to be a memory leak with the clock format command. I've
> tested this in freewrap 6.74 on Windows and tclsh 8.6 on Linux with
> the same result.
>
> Using this code:
>
> for { set i 0 } { $i < 1000 } { incr i } { clock format 0 -format
> [expr rand()] }

Leaks in 8.6.12 (64bit) on Linux. This results in an ever growing
process size shown in top:

while true { clock format 0 -format [expr rand()] }

[Rolf Ade]

John Jester <kuulg...@gmail.com> writes:

> There seems to be a memory leak with the clock format command. I've
> tested this in freewrap 6.74 on Windows and tclsh 8.6 on Linux with
> the same result.
>
> Using this code:
>
> for { set i 0 } { $i < 1000 } { incr i } { clock format 0 -format [expr rand()] }
>
> I see an increase in memory of about ~2 MB. Increasing the limit from
> 1,000 to 10,000 yields a memory increase of ~20 MB, so it seems linear
> at about 2 kB leaked per iteration. Same for 100,0000, with ~200 MB
> increase.

From what I see this is not lost memory in the sense of a true memory
link - true here means the application has allocated memory but lost any
reference to that. Valgrind doesn't show anything new.

But yes, this is a way to make a Tcl process go out of any bound with
respect to maximum resident memory size.

It's the always changed -format option, which makes this. See this
script:

proc doit {nr} {
for { set i 0 } { $i < $nr } { incr i } {
clock format 0 -format $i
}
}
doit $argv

Called with the arugments 1000, 10000, 20000 etc shows an alway linar
growing maximum resident set size of the process during its lifetime.

This script

proc doit {nr} {
for { set i 0 } { $i < $nr } { incr i } {
clock format $i -format 0
}
}
doit $argv

called with the arugments 1000, 10000, 20000 etc have all the same (low)
maximum resident set size of the process during its lifetime (as
expected). And run more than a magnitude faster as above.

There's some caching of processing of the -format specification in
place, or something like this.

The assumption (and probably not an immediately unreasonable) here seems
to be that you have only at max a few handful different formats but you
use any of this formats potentially again and again for different
values. And that should be fast. Think: Timestamp in an ever growing log
file.

Or so it looks at least from outside. I haven't looked so far on the
implementation.

rolf

[John Jester]

Thank you both for confirming the issue!

The reason I'm dealing with this is I'm trying to make a "clock format" that works with milli- or microseconds. Does anyone have a recommendation for a better way to do this?

[Andreas Leitgeb]

John Jester <kuulg...@gmail.com> wrote:
> The reason I'm dealing with this is I'm trying to make a
> "clock format" that works with milli- or microseconds.
> Does anyone have a recommendation for a better way to do this?

My suggestion: replace the %uS by a fixed string unlikely to
ever occur in a clock format result..., e.g. by %%uS, and then
use string map on the result (of the internal call) to replace
the %uS by the microseconds.

If you can accept a compromise for calling your custom clock format
then let users call it with %%uS (double percent), then your procedure
could pass the format string on to normal clock format directly, and
only needs to postprocess the result for %uS.

Passing it on directly should give a speed benefit, as clock
format seems to add stuff to the internal object of the format-
string, and by not recalculating it on each call, the cache
will accellerate future calls.

[Schelte]

On
https://wiki.tcl-lang.org/page/Add+a+time+stamp+to+each+line+of+output
I'm using %n for milliseconds and %v for microseconds.

I guess that code could benefit from the insights gained here. In other
words, do the clock format first and mapping %n and %v later. That is
possible because the clock command leaves format groups it doesn't know
alone. The advantage of doing the mapping first was that it would still
work if those format groups would be added to the clock command in the
future.


Schelte.

[Schelte]

On 18/05/2023 12:08, Schelte wrote:
> On
> https://wiki.tcl-lang.org/page/Add+a+time+stamp+to+each+line+of+output
> I'm using %n for milliseconds and %v for microseconds.
>
> I guess that code could benefit from the insights gained here. In other
> words, do the clock format first and mapping %n and %v later. That is
> possible because the clock command leaves format groups it doesn't know
> alone. The advantage of doing the mapping first was that it would still
> work if those format groups would be added to the clock command in the
> future.
>

Unfortunately that didn't work out because the clock code replaces %n
with \n, even though that is not documented in the manual page.

I'm going to have to pick a different letter for milliseconds, or fix it
some other way.


Schelte.

[Andreas Leitgeb]

Schelte <nos...@wanadoo.nl> wrote:
> On 18/05/2023 11:36, Andreas Leitgeb wrote:
>> John Jester <kuulg...@gmail.com> wrote:
>>> The reason I'm dealing with this is I'm trying to make a
>>> "clock format" that works with milli- or microseconds.
>>> Does anyone have a recommendation for a better way to do this?
>> My suggestion: replace the %uS by a fixed string unlikely to
>> ever occur in a clock format result..., e.g. by %%uS, and then
>> use string map on the result (of the internal call) to replace
>> the %uS by the microseconds.
>>
>> If you can accept a compromise for calling your custom clock format
>> then let users call it with %%uS (double percent), then your procedure
>> could pass the format string on to normal clock format directly, and
>> only needs to postprocess the result for %uS.
>>
>> Passing it on directly should give a speed benefit, as clock
>> format seems to add stuff to the internal object of the format-
>> string, and by not recalculating it on each call, the cache
>> will accellerate future calls.
>>
> On
> https://wiki.tcl-lang.org/page/Add+a+time+stamp+to+each+line+of+output
> I'm using %n for milliseconds and %v for microseconds.

I can't seem to log in on the page... It immediately asks
me for a maintainer login. (my browser had a username and password
in its vault, so I think the uid/pw was likely correct, just not
maintainer-level.

> I guess that code could benefit from the insights gained here. In other
> words, do the clock format first and mapping %n and %v later. That is
> possible because the clock command leaves format groups it doesn't know
> alone. The advantage of doing the mapping first was that it would still
> work if those format groups would be added to the clock command in the
> future.

On one hand, it would be a benefit, if clock format starts using the
same letter for the same thing: then the wrapper just becomes a no-op
(at merely the cost of string map not finding anything to replace).

On the other hand, there's the risk, that clock format will later choose
it for something else... then people would start getting strange stuff in
their logs.

For those feeling like gambling, the "one hand" seems attractive, for
the others, using %%v and %%n puts them on safe side - after the code
is changed to do the replacement only afterwards.

[John Jester]

On Thursday, May 18, 2023 at 2:36:36 AM UTC-7, Andreas Leitgeb wrote:
> My suggestion: replace the %uS by a fixed string unlikely to
> ever occur in a clock format result..., e.g. by %%uS, and then
> use string map on the result (of the internal call) to replace
> the %uS by the microseconds.

This has worked beautifully, thank you!

I allow the user to pass %us or %ms to my wrapper, which pre-processes with a string map to replace them with %%us or %%ms, then calls real clock which reverts them back to %us and %ms (as well as doing the whole format), then the wrapper post-processes the result with another string map to replace %us or %ms with the value for micro- or milliseconds. All with no memory leak since clock format is always passed the same format string.

Thanks all, problem solved on my end. Though Tcl still has the memory leak...

[Ivan Shmakov]

>>>>> On 2023-05-18, Andreas Leitgeb wrote:
>>>>> John Jester <kuulg...@gmail.com> wrote:

>> The reason I'm dealing with this is I'm trying to make a
>> "clock format" that works with milli- or microseconds.

>> Does anyone have a recommendation for a better way to do this?

> My suggestion: replace the %uS by a fixed string unlikely to
> ever occur in a clock format result..., e.g. by %%uS, and then
> use string map on the result (of the internal call) to replace
> the %uS by the microseconds.

FWIW, it's possible to use subst here. Consider, e. g.:

proc clock-fmt-ns { fmt ts } {
set int [ expr { int ($ts) } ]
set f [ expr { $ts - $int } ]
set ms [ format %03d [ expr { round (1e3 * $f) } ] ]
set us [ format %06d [ expr { round (1e6 * $f) } ] ]
set ns [ format %09d [ expr { round (1e9 * $f) } ] ]
subst -nocommands [ clock format $int -format $fmt ]
}

puts [ clock-fmt-ns {%Y-%m-%d %T.${ms}
%Y-%m-%d %T.${us}
%Y-%m-%d %T.${ns}} 1684417855.253717 ]
## Output:
## 2023-05-18 13:50:55.254
## 2023-05-18 13:50:55.253717
## 2023-05-18 13:50:55.253716946

(Obviously floats like the one above lack precision for
nanosecond-resolution timestamps; though, say, INTEGRAL.FRACTIONAL
strings can be used instead.)

--
FSF associate member #7257 http://am-1.org/~ivan/

[Rolf Ade]

John Jester <kuulg...@gmail.com> writes:
> On Thursday, May 18, 2023 at 2:36:36 AM UTC-7, Andreas Leitgeb wrote:
>> My suggestion: replace the %uS by a fixed string unlikely to
>> ever occur in a clock format result..., e.g. by %%uS, and then
>> use string map on the result (of the internal call) to replace
>> the %uS by the microseconds.
>
> This has worked beautifully, thank you!

> [...]

> Thanks all, problem solved on my end. Though Tcl still has the memory leak...

Fine that you have found a working solution for you problem.

As already suspected in my prior analysis this is not a memory leak in a
strong sense. It's a deliberate detail of the implementation. See this
comment:

https://core.tcl-lang.org/tcl/file?udc=1&ln=1455-1482&ci=b1fc8161f1f67f28&name=library%2Fclock.tcl

and study the proc implementation for how it is done. In short for every
-format and -locale combination an own parsing procedure is created (and
such scan procedures are not deleted once installed).

This script shows this:

proc doit {nr} {
for { set i 0 } { $i < $nr } { incr i } {
clock format 0 -format $i
}
}

# Populate the ::tcl::clock namespace with a first call
clock format 0

puts "Procs in the namespace ::tcl::clock [llength [info proc ::tcl::clock::*]]"
doit 1000
puts "Procs in the namespace ::tcl::clock [llength [info proc ::tcl::clock::*]]"

==>
Procs in the namespace ::tcl::clock 52
Procs in the namespace ::tcl::clock 1052

Now, if that should stay this way or if that could or should be
implemented in another way without that side effect or if a knob or flag
should be added for use cases like you had is another question.

rolf

[Robert Heller]

At Thu, 18 May 2023 17:03:55 +0200 Rolf Ade <ro...@pointsman.de> wrote:

>
>
> John Jester <kuulg...@gmail.com> writes:

So I guess if one is computing a one-time format for clock format (eg [clock
format ... -format $x]), then one needs to do a rename of
::tcl::clock::formatproc'$x'c to the empty string:

proc clockformatonetime {time fmt} {
set result [clock format $time -format $fmt]
rename ::tcl::clock::formatproc'$fmt'c {}
return $result
}

This should free up the space (or really recycle it).

Yep that works:

% proc doit {nr} {

for { set i 0 } { $i < $nr } { incr i } {
clock format 0 -format $i

rename ::tcl::clock::formatproc'$i'c {}
}
}
% clock format 0
Wed Dec 31 19:00:00 EST 1969
% puts "Procs in the namespace ::tcl::clock [llength [info proc ::tcl::clock::*]]"

Procs in the namespace ::tcl::clock 52

% doit 1000
% puts "Procs in the namespace ::tcl::clock [llength [info proc ::tcl::clock::*]]"

Procs in the namespace ::tcl::clock 52


>

> rolf
>
>
>
>
>
>

--
Robert Heller -- Cell: 413-658-7953 GV: 978-633-5364
Deepwoods Software -- Custom Software Services
http://www.deepsoft.com/ -- Linux Administration Services
hel...@deepsoft.com -- Webhosting Services

[Andreas Leitgeb]

John Jester <kuulg...@gmail.com> wrote:
> On Thursday, May 18, 2023 at 2:36:36 AM UTC-7, Andreas Leitgeb wrote:
>> My suggestion: replace the %uS by a fixed string unlikely to
>> ever occur in a clock format result..., e.g. by %%uS, and then
>> use string map on the result (of the internal call) to replace
>> the %uS by the microseconds.
> This has worked beautifully, thank you!
> I allow the user to pass %us or %ms to my wrapper, which pre-processes
> with a string map to replace them with %%us or %%ms, then calls real
> clock which reverts them back to %us and %ms (as well as doing the
> whole format), then the wrapper post-processes the result with another
> string map to replace %us or %ms with the value for micro- or
> milliseconds.

Now that you've gone so far, do some timing tests, and judge, whether
it would be worth asking the users to use %%us or %%ms themselves
and yor procedure only doing the postprocessing. (The timing difference
will likely be *much* more than just the time for preprocessing of
the format-string, at least if lots of loglines are written)

> All with no memory leak since clock format is always
> passed the same format string.

Yes, that's the main advantage.

[Rolf Ade]

Robert Heller <hel...@deepsoft.com> writes:
> At Thu, 18 May 2023 17:03:55 +0200 Rolf Ade <ro...@pointsman.de> wrote:
>> As already suspected in my prior analysis this is not a memory leak in a
>> strong sense. It's a deliberate detail of the implementation. See this
>> comment:
>>
>> https://core.tcl-lang.org/tcl/file?udc=1&ln=1455-1482&ci=b1fc8161f1f67f28&name=library%2Fclock.tcl

>> [...]

>> Now, if that should stay this way or if that could or should be
>> implemented in another way without that side effect or if a knob or flag
>> should be added for use cases like you had is another question.
>
> So I guess if one is computing a one-time format for clock format (eg [clock
> format ... -format $x]), then one needs to do a rename of
> ::tcl::clock::formatproc'$x'c to the empty string:
>
> proc clockformatonetime {time fmt} {
> set result [clock format $time -format $fmt]
> rename ::tcl::clock::formatproc'$fmt'c {}
> return $result
> }
>
> This should free up the space (or really recycle it).

Yes, of course. You can hack your way around this implementation detail
with something like this. If you remember this thread at the occasion
you need to or should remember it. And for a general solution you need
to care about the other possible options (-base, -gmt, -locale,
-timezone) and that the scanner procs are build from the -format and
-locale combination.

Since the documentation doesn't say something about this (if I haven't
missed something) that's perhaps a tad too much detail and special case
knowledge expected from Joe Programmer.

Maybe at least a -once flag with three lines of explanation in the
documentation would be better (if it seems to much work / hassle /
otherwise to detrimental to reach out for another implementation which
avoids this side effect).

rolf

[Andreas Leitgeb]

Rolf Ade <ro...@pointsman.de> wrote:
> Maybe at least a -once flag ...

or "-nocache" ... But I'm not going to TIP it.

I think, the usecase is wrong-headed. "One-time" formats
are just pretty inefficient.

[Rolf Ade]

Andreas Leitgeb <a...@logic.at> writes:
> Rolf Ade <ro...@pointsman.de> wrote:
>> Maybe at least a -once flag ...
>
> or "-nocache" ... But I'm not going to TIP it.

Me neither. And for the same reason - I'm not convinced there is a
serious use case for it.

But still ... In general I think I prefer if Tcl would do even nonsense
thinks gracefully. And in this case it does not.

rolf

[Harald Oehlmann]

John,
if you want to look in speed-up of the clock command, magic Sergey
Brester, has made a speed-up of factor 20 implementation.

It is in the TCL branch
https://core.tcl-lang.org/tcl/timeline?r=sebres-8-7-clock-speedup-cr2

It would be great, if this gem could be considered and merged one day.
Unfortunately, the work of Sergey is so high level, that nobody eles
understands it. There are a couple of propositions by him in core
branches, all starting with "sebres" (his login).

Take care,
Harald

[rene]

With all the tct changes underway we should try to convince sebres to join again.

rene

[Ralf Fassel]

* Rolf Ade <ro...@pointsman.de>

| John Jester <kuulg...@gmail.com> writes:
>
| > There seems to be a memory leak with the clock format command. I've
| > tested this in freewrap 6.74 on Windows and tclsh 8.6 on Linux with
| > the same result.

--<snip-snip>--

>
| It's the always changed -format option, which makes this.

--<snip-snip>--

| There's some caching of processing of the -format specification in
| place, or something like this.

For each format, a cached proc is created in library/clock.tcl, and
cleared only if the locale changes.

proc ::tcl::clock::Initialize {} {
variable FormatProc; # Array mapping format group
# and locale to the name of a procedure
# that renders the given format

proc ::tcl::clock::format
# Build a procedure to format the result. Cache the built procedure's name
# in the 'FormatProc' array to avoid losing its internal representation,
# which contains the name resolution.

for { set i 0 } { $i < 1000 } { incr i } {

clock format 0 -format [expr rand()] ;
puts [array size tcl::clock::FormatProc]
}
=>
1
2
3
...
1000

So this seems to be Broken As Designed...

R'