zef performance improvement

[melezhik]

Quoting my thoughts from IRC:

It took 22 minutes to test CSS module on RakuDist, now sure why it's so long, from that almost 10 minutes zef built dependency tree, which is just a few modules.

https://rakudist.raku.org/sparky/report/debian/152

18:31:14 06/01/2020 ... 18:52

oh, I see they are not just a few, but still imho 10 minutes to build a dependency tree a bit too much, somehow we need to think about zef performance improving in that case ...

[ugexe]

Have you considered that rakudo itself is the issue? Is there any proof zef is the issue, like anyone else having this problem or the problem in general being reproducible?

[ugexe]

If you can reproduce this outside of a CI environment please reopen. Otherwise I can only assume it is rakudo itself.

[melezhik]

@ugexe why do you think it's rakudo related ? the log shows timestamps for a certain operations of zef dependency build ... how does this relate to rakudo?

CSS module Travis CI shows some numbers, but unfortunately it does not show a portion of time required to build a tree ( RakuDist does )

https://travis-ci.org/github/p6-css/CSS-raku/jobs/657366796

cc @dwarring

[ugexe]

Well first... can you reproduce it easily? I cannot determine that from just one run, and I do not get the same result (1m)

$ time perl6 -I. bin/zef install CSS --debug --/fetch --/build --/test --dry --/cached
===> Searching for: CSS
===> Updating cpan mirror: https://raw.githubusercontent.com/ugexe/Perl6-ecosystems/master/cpan1.json
===> Updating p6c mirror: https://raw.githubusercontent.com/ugexe/Perl6-ecosystems/master/p6c1.json
===> Updated p6c mirror: https://raw.githubusercontent.com/ugexe/Perl6-ecosystems/master/p6c1.json
===> Updated cpan mirror: https://raw.githubusercontent.com/ugexe/Perl6-ecosystems/master/cpan1.json
===> Found: CSS:ver<0.0.4> [via Zef::Repository::Ecosystems<cpan>]
===> Dependencies: LibXML, CSS::Module, CSS::Properties, CSS::Selector::To::XPath
===> Searching for missing dependencies: LibXML, CSS::Module, CSS::Properties:ver<0.5.0+>, CSS::Selector::To::XPath
===> Found dependencies: LibXML:ver<0.4.0>:auth<cpan:WARRINGD>, CSS::Selector::To::XPath:ver<0.0.6> [via Zef::Repository::Ecosystems<cpan>]
===> Found dependencies: CSS::Module:ver<0.5.2>:auth<github:css-raku>:api<css.snapshot.2010>, CSS::Properties:ver<0.5.1>:auth<github:p6-css> [via Zef::Repository::Ecosystems<p6c>]
===> Dependencies: CSS::Module::CSS3::Selectors, CSS::Specification, CSS::Writer, JSON::Fast, CSS::Module, CSS::Box, Color, Method::Also, XML, File::Temp
===> Searching for missing dependencies: CSS::Module::CSS3::Selectors, CSS::Specification, CSS::Writer, Color, Method::Also, XML
===> Found dependencies: Method::Also:ver<0.0.5>:auth<cpan:ELIZABETH> [via Zef::Repository::Ecosystems<cpan>]
===> Found dependencies: CSS::Module::CSS3::Selectors:ver<0.0.3>:auth<github:p6-css>:api<css.3.selectors.20110929>, Color:ver<1.002008>, CSS::Specification:ver<0.4.6>, XML:ver<0.3.0>:auth<Timothy Totten>, CSS::Writer:ver<0.2.5> [via Zef::Repository::Ecosystems<p6c>]
===> Dependencies: CSS::Grammar, JSON::Fast, Color::Names
===> Searching for missing dependencies: CSS::Grammar:ver<0.3.3+>, CSS::Grammar, Color::Names
===> Found dependencies: CSS::Grammar:ver<0.3.4>:auth<github:css-raku> [via Zef::Repository::Ecosystems<p6c>]
===> Found dependencies: Color::Names:ver<1.001003> [via Zef::Repository::Ecosystems<cpan>]
===> Dependencies: JSON::Fast
Too few positionals passed to 'make-install'; expected at least 1 argument but got only 0 in sub-signature of parameter @candidates

real    1m0.850s
user    2m37.556s
sys 0m2.255s

[melezhik]

interesting ... let me rerun RakuDist ....

[melezhik]

which version of Raku and zef do you in your test BTW?

[melezhik]

nevermind, I started to suspect it could be not zef but probably combination of things ... Maybe even because Sparrow runs zef install as sub process and there is something makes it wait till it closes the process ... I don't know, I need to investigate ...

[ugexe]

Oh that is a good point. It looks like stdout/stderr (for rakudist) was getting buffered while it was doing work, and then all output at once (which I presume based on the fact it otherwise tests all the dists in a matter of 2 seconds).

[melezhik]

hm. now when I run only this certain bit through Sparrow on docker instance, time is acceptable. So it could be bottle neck somewhere else:

root@f26113e6fdad:/# time s6 --plg-run bash@command="zef install CSS --debug --/fetch --/build --/test --dry --/cached",user=wplhisxjtyzfugdnorvm21:43:38 06/01/2020 [task] run plg bash@command=zef install CSS --debug --/fetch --/build --/test --dry --/cached,user=wplhisxjtyzfugdnorvm
21:43:38 06/01/2020 [task] run thing bash
21:44:13 06/01/2020 [bash] ===> Searching for: CSS
21:44:13 06/01/2020 [bash] stderr: ===> Updating cpan mirror: https://raw.githubusercontent.com/ugexe/Perl6-ecosystems/master/cpan1.json
21:45:06 06/01/2020 [bash] ===> Found: CSS:ver<0.0.4> [via Zef::Repository::Ecosystems<cpan>]
21:45:06 06/01/2020 [bash] ===> Dependencies: LibXML, CSS::Module, CSS::Properties, CSS::Selector::To::XPath
21:45:06 06/01/2020 [bash] ===> Searching for missing dependencies: LibXML, CSS::Module, CSS::Properties:ver<0.5.0+>, CSS::Selector::To::XPath
21:45:06 06/01/2020 [bash] ===> Found dependencies: CSS::Module:ver<0.5.2>:auth<github:css-raku>:api<css.snapshot.2010>, CSS::Properties:ver<0.5.1>:auth<github:p6-css> [via Zef::Repository::Ecosystems<p6c>]
21:45:06 06/01/2020 [bash] ===> Found dependencies: LibXML:ver<0.4.0>:auth<cpan:WARRINGD>, CSS::Selector::To::XPath:ver<0.0.6> [via Zef::Repository::Ecosystems<cpan>]
21:45:06 06/01/2020 [bash] ===> Dependencies: CSS::Module::CSS3::Selectors, CSS::Specification, CSS::Writer, JSON::Fast, CSS::Module, CSS::Box, Color, Method::Also, XML, File::Temp
21:45:06 06/01/2020 [bash] ===> Searching for missing dependencies: CSS::Module::CSS3::Selectors, CSS::Specification, CSS::Writer, JSON::Fast, Color, Method::Also, XML, File::Temp
21:45:06 06/01/2020 [bash] ===> Found dependencies: CSS::Module::CSS3::Selectors:ver<0.0.3>:auth<github:p6-css>:api<css.3.selectors.20110929>, Color:ver<1.002008>, CSS::Specification:ver<0.4.6>, XML:ver<0.3.0>:auth<Timothy Totten>, CSS::Writer:ver<0.2.5> [via Zef::Repository::Ecosystems<p6c>]
21:45:06 06/01/2020 [bash] ===> Found dependencies: JSON::Fast:ver<0.10>, File::Temp:ver<0.0.8>, Method::Also:ver<0.0.5>:auth<cpan:ELIZABETH> [via Zef::Repository::Ecosystems<cpan>]
21:45:06 06/01/2020 [bash] ===> Dependencies: CSS::Grammar, JSON::Fast, Color::Names, File::Directory::Tree
21:45:06 06/01/2020 [bash] ===> Searching for missing dependencies: CSS::Grammar:ver<0.3.3+>, CSS::Grammar, Color::Names, File::Directory::Tree
21:45:06 06/01/2020 [bash] ===> Found dependencies: Color::Names:ver<1.001003> [via Zef::Repository::Ecosystems<cpan>]
21:45:06 06/01/2020 [bash] ===> Found dependencies: CSS::Grammar:ver<0.3.4>:auth<github:css-raku>, File::Directory::Tree:auth<labster> [via Zef::Repository::Ecosystems<p6c>]
21:45:06 06/01/2020 [bash] ===> Dependencies: JSON::Fast
21:45:06 06/01/2020 [bash] stderr: ===> Updating p6c mirror: https://raw.githubusercontent.com/ugexe/Perl6-ecosystems/master/p6c1.json
===> Updated p6c mirror: https://raw.githubusercontent.com/ugexe/Perl6-ecosystems/master/p6c1.json
===> Updated cpan mirror: https://raw.githubusercontent.com/ugexe/Perl6-ecosystems/master/cpan1.json
Too few positionals passed to 'make-install'; expected at least 1 argument but got only 0 in sub-signature of parameter @candidates
21:45:06 06/01/2020 [bash] task exit status: 1
21:45:06 06/01/2020 [bash] task bash FAILED

real    1m29.812s
user    5m52.645s
sys     0m10.068s

[melezhik]

Let me do real install without dry-run ...

[ugexe]

It’s on your end. Look at the time stamps. Do you really think every dependency tests ran in 2 seconds? No, something was hung up buffering stdout/stderr in e.g. Sparrow

[melezhik]

Do you really think every dependency tests ran in 2 seconds?

No they don't , it's just how Sparrow works. It gets buffered output and then print it out line by line, adding timestamp for every line, so timestamps in Sparrow log could be confusing at times.

Anyway, I've run now pure test using time s6 --plg-run bash@command="zef install CSS",user=wplhisxjtyzfugdnorvm and will show us a certain time.

[melezhik]

BTW meanwhile could you please run time zef install CSS on fresh environment so we can compare time for real install, not dry-run ?

[ugexe]

...right, I’m also saying the time output is wrong. It takes 10 minutes to do everything.

[melezhik]

root@f26113e6fdad:/# time s6 --plg-run bash@command="zef install CSS",user=wplhisxjtyzfugdnorvm                                                  21:50:24 06/01/2020 [task] run plg bash@command=zef install CSS,user=wplhisxjtyzfugdnorvm
21:50:24 06/01/2020 [task] run thing bash
21:50:28 06/01/2020 [bash] ===> Searching for: CSS
22:03:22 06/01/2020 [bash] stderr: CSS::Properties::Box is deprecated. Please use CSS::Box
  in block <unit> at /home/wplhisxjtyzfugdnorvm/.raku/sources/69D7D9C42
22:03:22 06/01/2020 [bash] stderr: F9A1A9867F7EA2473DC56F0A78421AE (CSS::Properties::Box) line 5
22:04:01 06/01/2020 [bash] ===> Searching for missing dependencies: LibXML, CSS::Module, CSS::Properties:ver<0.5.0+>, CSS::Selector::To::XPath
22:04:01 06/01/2020 [bash] ===> Searching for missing dependencies: CSS::Module::CSS3::Selectors, CSS::Specification, CSS::Writer, JSON::Fast, Color, Method::Also, XML, File::Temp, LibraryMake, Pod::To::Markdown
22:04:01 06/01/2020 [bash] ===> Searching for missing dependencies: CSS::Grammar:ver<0.3.3+>, Shell::Command, CSS::Grammar, Color::Names, File::Directory::Tree, Pod::To::HTML
22:04:01 06/01/2020 [bash] ===> Searching for missing dependencies: Test::META, URI, Template::Mustache, Pod::Load:ver<0.4.0+>, Test::Output, File::Which, File::Find
22:04:01 06/01/2020 [bash] ===> Searching for missing dependencies: META6, License::SPDX
22:04:01 06/01/2020 [bash] ===> Searching for missing dependencies: JSON::Class:ver<0.0.14+>, JSON::Class:ver<0.0.5+>
22:04:01 06/01/2020 [bash] ===> Searching for missing dependencies: JSON::Marshal:ver<0.0.18+>, JSON::Unmarshal:ver<0.08+>
22:04:01 06/01/2020 [bash] ===> Searching for missing dependencies: JSON::Name
22:04:01 06/01/2020 [bash] ===> Building: LibXML:ver<0.4.0>:auth<cpan:WARRINGD>
22:04:01 06/01/2020 [bash] ===> Building [OK] for LibXML:ver<0.4.0>:auth<cpan:WARRINGD>
22:04:01 06/01/2020 [bash] ===> Testing: XML:ver<0.3.0>:auth<Timothy Totten>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for XML:ver<0.3.0>:auth<Timothy Totten>
22:04:01 06/01/2020 [bash] ===> Testing: Method::Also:ver<0.0.5>:auth<cpan:ELIZABETH>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Method::Also:ver<0.0.5>:auth<cpan:ELIZABETH>
22:04:01 06/01/2020 [bash] ===> Testing: File::Directory::Tree:auth<labster>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for File::Directory::Tree:auth<labster>
22:04:01 06/01/2020 [bash] ===> Testing: File::Temp:ver<0.0.8>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for File::Temp:ver<0.0.8>
22:04:01 06/01/2020 [bash] ===> Testing: File::Which:ver<1.0.1>
22:04:01 06/01/2020 [bash] [File::Which] # Found perl6 at '/tmp/whateverable/rakudo-moar/002acb1be2ba2a47ef8a48c30c340d43df91abed/bin/perl6'
22:04:01 06/01/2020 [bash] [File::Which] # Found perl6 at '/tmp/whateverable/rakudo-moar/002acb1be2ba2a47ef8a48c30c340d43df91abed/bin/perl6' using whence
22:04:01 06/01/2020 [bash] ===> Testing [OK] for File::Which:ver<1.0.1>
22:04:01 06/01/2020 [bash] ===> Testing: File::Find:ver<0.1>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for File::Find:ver<0.1>
22:04:01 06/01/2020 [bash] ===> Testing: Shell::Command
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Shell::Command
22:04:01 06/01/2020 [bash] ===> Testing: LibraryMake:ver<1.0.0>:auth<github:retupmoca>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for LibraryMake:ver<1.0.0>:auth<github:retupmoca>
22:04:01 06/01/2020 [bash] ===> Testing: URI:ver<0.3.0>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for URI:ver<0.3.0>
22:04:01 06/01/2020 [bash] ===> Testing: JSON::Fast:ver<0.10>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for JSON::Fast:ver<0.10>
22:04:01 06/01/2020 [bash] ===> Testing: JSON::Name:ver<0.0.4>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for JSON::Name:ver<0.0.4>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing: JSON::Marshal:ver<0.0.18>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for JSON::Marshal:ver<0.0.18>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing: JSON::Unmarshal:ver<0.08>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for JSON::Unmarshal:ver<0.08>
22:04:01 06/01/2020 [bash] ===> Testing: JSON::Class:ver<0.0.14>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for JSON::Class:ver<0.0.14>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing: META6:ver<0.0.23>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for META6:ver<0.0.23>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing: License::SPDX:ver<3.9.0>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for License::SPDX:ver<3.9.0>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing: Test::META:ver<0.0.16>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] [Test::META] # the following may make some diagnostics from the module itself
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Test::META:ver<0.0.16>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Testing: Template::Mustache:ver<1.1.4>:auth<github:softmoth>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Template::Mustache:ver<1.1.4>:auth<github:softmoth>
22:04:01 06/01/2020 [bash] ===> Testing: Pod::Load:ver<0.5.5>
22:04:01 06/01/2020 [bash] [Pod::Load] # Testing strings
22:04:01 06/01/2020 [bash] [Pod::Load] # Testing files
22:04:01 06/01/2020 [bash] [Pod::Load] # Testing strings with metadata
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Pod::Load:ver<0.5.5>
22:04:01 06/01/2020 [bash] ===> Testing: Test::Output:ver<1.001002>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Test::Output:ver<1.001002>
22:04:01 06/01/2020 [bash] ===> Testing: Pod::To::HTML:ver<0.7.0>:auth<github:Raku>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Pod::To::HTML:ver<0.7.0>:auth<github:Raku>
22:04:01 06/01/2020 [bash] ===> Testing: Pod::To::Markdown:ver<v.0.1.4>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Pod::To::Markdown:ver<v.0.1.4>
22:04:01 06/01/2020 [bash] ===> Testing: LibXML:ver<0.4.0>:auth<cpan:WARRINGD>
22:04:01 06/01/2020 [bash] [LibXML] # Running libxml2 version: 2.09.04 (module 0.4.0)
22:04:01 06/01/2020 [bash] [LibXML] parse :$io tests need Rakudo > 2020.05
22:04:01 06/01/2020 [bash] [LibXML] parse :$io tests need Rakudo > 2020.05
22:04:01 06/01/2020 [bash] [LibXML] parse :$io tests need Rakudo > 2020.05
22:04:01 06/01/2020 [bash] ===> Testing [OK] for LibXML:ver<0.4.0>:auth<cpan:WARRINGD>
22:04:01 06/01/2020 [bash] ===> Testing: CSS::Grammar:ver<0.3.4>:auth<github:css-raku>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for CSS::Grammar:ver<0.3.4>:auth<github:css-raku>
22:04:01 06/01/2020 [bash] ===> Testing: CSS::Module::CSS3::Selectors:ver<0.0.3>:auth<github:p6-css>:api<css.3.selectors.20110929>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for CSS::Module::CSS3::Selectors:ver<0.0.3>:auth<github:p6-css>:api<css.3.selectors.20110929>
22:04:01 06/01/2020 [bash] ===> Testing: Color::Names:ver<1.001003>
22:04:01 06/01/2020 [bash] [Color::Names]     # the licence ‘GPL-3.0’ is valid but deprecated, you may want to use another license.
22:04:01 06/01/2020 [bash] [Color::Names]     #
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Color::Names:ver<1.001003>
22:04:01 06/01/2020 [bash] ===> Testing: CSS::Specification:ver<0.4.6>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for CSS::Specification:ver<0.4.6>
22:04:01 06/01/2020 [bash] ===> Testing: CSS::Writer:ver<0.2.5>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for CSS::Writer:ver<0.2.5>
22:04:01 06/01/2020 [bash] ===> Testing: CSS::Module:ver<0.5.2>:auth<github:css-raku>:api<css.snapshot.2010>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for CSS::Module:ver<0.5.2>:auth<github:css-raku>:api<css.snapshot.2010>
22:04:01 06/01/2020 [bash] ===> Testing: Color:ver<1.002008>
22:04:01 06/01/2020 [bash] [Color] # Short 3-hex
22:04:01 06/01/2020 [bash] [Color] # Short 4-hex
22:04:01 06/01/2020 [bash] [Color] # Full 6-hex
22:04:01 06/01/2020 [bash] [Color] # Full 8-hex
22:04:01 06/01/2020 [bash] [Color] # RGB tuple
22:04:01 06/01/2020 [bash] [Color] # RGB tuple (decimal form)
22:04:01 06/01/2020 [bash] [Color] # RGBA tuple
22:04:01 06/01/2020 [bash] [Color] # RGBA tuple (decimal form)
22:04:01 06/01/2020 [bash] [Color] # CMYK tuple
22:04:01 06/01/2020 [bash] [Color] # HSL tuple
22:04:01 06/01/2020 [bash] [Color] # HSLA tuple
22:04:01 06/01/2020 [bash] [Color] # HSV tuple
22:04:01 06/01/2020 [bash] [Color] # HSVA tuple
22:04:01 06/01/2020 [bash] [Color] # Short 3-hex
22:04:01 06/01/2020 [bash] [Color] # Short 4-hex
22:04:01 06/01/2020 [bash] [Color] # Full 6-hex
22:04:01 06/01/2020 [bash] [Color] # Full 8-hex
22:04:01 06/01/2020 [bash] [Color] # RGB tuple
22:04:01 06/01/2020 [bash] [Color] # CMYK tuple
22:04:01 06/01/2020 [bash] [Color] # Key-value forms
22:04:01 06/01/2020 [bash] [Color] # Operator tests on rgb nums
22:04:01 06/01/2020 [bash] [Color] # Operator tests (alpha-math turned off on rgba nums)
22:04:01 06/01/2020 [bash] [Color] # Try again with enabled alpha math
22:04:01 06/01/2020 [bash] [Color] # Try again with enabled alpha math
22:04:01 06/01/2020 [bash] [Color] # Our fancy-pants unicode ops
22:04:01 06/01/2020 [bash] [Color] # Tests on alpha channel behavior
22:04:01 06/01/2020 [bash] ===> Testing [OK] for Color:ver<1.002008>
22:04:01 06/01/2020 [bash] ===> Testing: CSS::Properties:ver<0.5.1>:auth<github:p6-css>
22:04:01 06/01/2020 [bash] [CSS::Properties] dropping unknown property: azimuth
22:04:01 06/01/2020 [bash] ===> Testing [OK] for CSS::Properties:ver<0.5.1>:auth<github:p6-css>
22:04:01 06/01/2020 [bash] ===> Testing: CSS::Selector::To::XPath:ver<0.0.6>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for CSS::Selector::To::XPath:ver<0.0.6>
22:04:01 06/01/2020 [bash] ===> Testing: CSS:ver<0.0.4>
22:04:01 06/01/2020 [bash] ===> Testing [OK] for CSS:ver<0.0.4>
22:04:01 06/01/2020 [bash] ===> Installing: XML:ver<0.3.0>:auth<Timothy Totten>
22:04:01 06/01/2020 [bash] ===> Installing: Method::Also:ver<0.0.5>:auth<cpan:ELIZABETH>
22:04:01 06/01/2020 [bash] ===> Installing: File::Directory::Tree:auth<labster>
22:04:01 06/01/2020 [bash] ===> Installing: File::Temp:ver<0.0.8>
22:04:01 06/01/2020 [bash] ===> Installing: File::Which:ver<1.0.1>
22:04:01 06/01/2020 [bash] ===> Installing: File::Find:ver<0.1>
22:04:01 06/01/2020 [bash] ===> Installing: Shell::Command
22:04:01 06/01/2020 [bash] ===> Installing: LibraryMake:ver<1.0.0>:auth<github:retupmoca>
22:04:01 06/01/2020 [bash] ===> Installing: URI:ver<0.3.0>
22:04:01 06/01/2020 [bash] ===> Installing: JSON::Fast:ver<0.10>
22:04:01 06/01/2020 [bash] ===> Installing: JSON::Name:ver<0.0.4>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Installing: JSON::Marshal:ver<0.0.18>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Installing: JSON::Unmarshal:ver<0.08>
22:04:01 06/01/2020 [bash] ===> Installing: JSON::Class:ver<0.0.14>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Installing: META6:ver<0.0.23>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Installing: License::SPDX:ver<3.9.0>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Installing: Test::META:ver<0.0.16>:auth<github:jonathanstowe>:api<1.0>
22:04:01 06/01/2020 [bash] ===> Installing: Template::Mustache:ver<1.1.4>:auth<github:softmoth>
22:04:01 06/01/2020 [bash] ===> Installing: Pod::Load:ver<0.5.5>
22:04:01 06/01/2020 [bash] ===> Installing: Test::Output:ver<1.001002>
22:04:01 06/01/2020 [bash] ===> Installing: Pod::To::HTML:ver<0.7.0>:auth<github:Raku>
22:04:01 06/01/2020 [bash] ===> Installing: Pod::To::Markdown:ver<v.0.1.4>
22:04:01 06/01/2020 [bash] ===> Installing: LibXML:ver<0.4.0>:auth<cpan:WARRINGD>
22:04:01 06/01/2020 [bash] ===> Installing: CSS::Grammar:ver<0.3.4>:auth<github:css-raku>
22:04:01 06/01/2020 [bash] ===> Installing: CSS::Module::CSS3::Selectors:ver<0.0.3>:auth<github:p6-css>:api<css.3.selectors.20110929>
22:04:01 06/01/2020 [bash] ===> Installing: Color::Names:ver<1.001003>
22:04:01 06/01/2020 [bash] ===> Installing: CSS::Specification:ver<0.4.6>
22:04:01 06/01/2020 [bash] ===> Installing: CSS::Writer:ver<0.2.5>
22:04:01 06/01/2020 [bash] ===> Installing: CSS::Module:ver<0.5.2>:auth<github:css-raku>:api<css.snapshot.2010>
22:04:01 06/01/2020 [bash] ===> Installing: Color:ver<1.002008>
22:04:01 06/01/2020 [bash] ===> Installing: CSS::Properties:ver<0.5.1>:auth<github:p6-css>
22:04:01 06/01/2020 [bash] ===> Installing: CSS::Selector::To::XPath:ver<0.0.6>
22:04:01 06/01/2020 [bash] ===> Installing: CSS:ver<0.0.4>
22:04:01 06/01/2020 [bash]
22:04:01 06/01/2020 [bash] 2 bin/ scripts [css-gen-properties.raku css-inliner.raku] installed to:
22:04:01 06/01/2020 [bash] /home/wplhisxjtyzfugdnorvm/.raku/bin

real    13m39.096s
user    27m57.897s
sys     1m23.454s

[melezhik]

Sparrow uses that piece of code to run sub processes - https://github.com/melezhik/Sparrow6/blob/master/lib/Sparrow6/Task/Runner/Helpers/Common.pm6#L90-L157

If there is any way to disable buffering, to have timestamps more sensible?

[melezhik]

I am going to run time zef install CSS directly, without Sparrow, right on docker and compare times

[ugexe]

Anytime I've seen this behavior I've gotten the feeling it was from something like the stdout reader getting blocked by the stderr reader (or vice-versa), and once the blocking reader finishes it can finally read from the other handle. I have no evidence of this... just a hunch.

[melezhik]

well , unfortunately my connection with server was broken during test run, but I must say time is comparable with Sparrow flavor run. We need more tests, but so far my impressions is that:

zef install CSS takes quite a time when running on docker, at least 10 minutes.

[ugexe]

How long it takes to install is irrelevant. It takes approximately 1 minute to handle the dependencies... 99% of the rest of the time is testing which runtime is dependent entirely on rakudo and not at all dependent on zef.

[melezhik]

How long it takes to install is irrelevant. It takes approximately 1 minute to handle the dependencies...

Absolutely, my first statement, that it's 10 minutes to build dependency tree for zef, was wrong. Now I see that.

Now, I want to to know why it is still ( quite a number ) 10 minutes to install around 10-15 dependencies. May be it's OK, as there is LibXML module for example which is quite heavy, but till I fix time-stamping in Sparrow we won't get more granular statistics.

[ugexe]

I mean it looks like a bunch of grammar-based modules, presumably with ample testing. It doesn't surprise me at all it takes that long to test+install given testing likely takes 99% of that time.

[melezhik]

yeah, maybe just a bad example to measure performance. and yeah I've barked up a wrong tree from the beginning.

[melezhik]

probably this commit - https://github.com/melezhik/sparrowdo/commit/d4ac80600cffe88d65231bae3131627ea24e3fb9 fixes the issue of stdout/stderr from docker

[melezhik]

at least in this build timestamps corresponds actual timing of steps executed

[melezhik]

http://rakudist.raku.org/sparky/report/debian/154

[melezhik]

sigh ... looks this does not help - http://rakudist.raku.org/sparky/report/debian/156 ...

[ugexe]

re: using .out-buffer -- I hope you understand how absurd it would be to expect all scripts written in raku to need to set that. Setting that might happen to work-around an issue, but it seems pretty clear the core raku buffering behavior is broken (and not that any raku script, including zef, is doing something wrong by not manually setting .out-buffer).

[melezhik]

yeah, so you mean, it's still rakudo side issue?

[ugexe]

Yes. Zef just launches processes to run raku code (test files), so in the case of .out-buffer unless every single module sets it then they could potentially lock-up zef in a similar way to what you are seeing with Sparrow and zef. Either something is wrong with the buffering itself, or the size of the buffer is calculated incorrectly for some systems (like those without a TTY maybe).

[melezhik]

(like those without a TTY maybe).

yeah, probably this explains why we see it in docker? As you could see, I tried to play with various kinds of flags to run docker exec, e.g. i, -t, but those don't remove the buffering from zef step ...

[melezhik]

looks like zef patch with .out-buffer = 0 does the trick.

https://rakudist.raku.org/sparky/report/debian/160

It works for RakuDist, I don't jump to any conclusion which blame it is ( rakudo or zef), at least I am happy with Sparrow timestamps now.

[ugexe]

Yeah, it would just be nice if it could be golfed down further so someone could try to fix it in the core. Anyway another way to sort-of patch zef behavior might be to do (untested):

# like `zef install .`
raku -MZef::CLI -e '($*OUT,$*ERR).map({ $_.output-buffer = 0 }).sink' install .