OPT+ENH: determine config to query for procedure once, add more "log(2," to eval_func

[yarikoptic]

Original OPT issue: #3575 . This PR addresses only one aspect, and doesn't touch upon relatively slow .config and .is_installed which are yet to be figured out and probably should be properly "lazied" at the dataset level since we are doing this over and over for every decorated function in the same dataset!

Those added debug statements seems to have no cost but could help determining unexpected
slow downs

For me it is cutting down time for a dummy datalad run from 2.9 to 2.2 sec (so ~20% boost! ;))

~datalad/datalad > time DATALAD_LOG_TIMESTAMP=1 datalad run --explicit --input benchmarks echo nothing todo 2>&1 | tools/dtime 
 1280 2019-08-01 11:40:50,695 [INFO] Making sure inputs are available (this may take some time) 
    - nothing todo
    3 2019-08-01 11:40:51,975 [INFO] == Command start (output follows) ===== 
----- 2019-08-01 11:40:51,978 [INFO] == Command exit (modification check follows) ===== 
DATALAD_LOG_TIMESTAMP=1 datalad run --explicit --input benchmarks echo nothin  2.02s user 0.21s system 100% cpu 2.221 total
tools/dtime  0.01s user 0.01s system 0% cpu 2.225 total

and I do not expect negative effect on other usecases.

[codecov]

Codecov Report

Merging #3576 into 0.11.x will decrease coverage by 18.2%.
The diff coverage is 86.66%.

@@             Coverage Diff             @@
##           0.11.x    #3576       +/-   ##
===========================================
- Coverage   77.29%   59.08%   -18.21%     
===========================================
  Files         255      255               
  Lines       33641    33645        +4     
===========================================
- Hits        26002    19879     -6123     
- Misses       7639    13766     +6127

Impacted Files	Coverage Δ
datalad/interface/utils.py	75.47% <86.66%> (-0.6%)	⬇️
datalad/interface/tests/test_save.py	16.3% <0%> (-83.7%)	⬇️
datalad/ui/tests/test_base.py	16.66% <0%> (-83.34%)	⬇️
datalad/distribution/tests/test_dataset.py	17.6% <0%> (-82.4%)	⬇️
datalad/metadata/tests/test_aggregation.py	17.84% <0%> (-81.23%)	⬇️
datalad/distribution/tests/test_siblings.py	19.14% <0%> (-80.86%)	⬇️
datalad/distribution/tests/test_dataset_binding.py	19.23% <0%> (-80.77%)	⬇️
datalad/interface/tests/test_base.py	19.48% <0%> (-80.52%)	⬇️
datalad/interface/tests/test_diff.py	22.03% <0%> (-77.97%)	⬇️
datalad/interface/tests/test_ls_webui.py	15.5% <0%> (-77.31%)	⬇️
... and 105 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update ebb8b93...fe9bff6. Read the comment docs.

[codecov]

Codecov Report

Merging #3576 into 0.11.x will decrease coverage by 18.2%.
The diff coverage is 86.66%.

@@             Coverage Diff             @@
##           0.11.x    #3576       +/-   ##
===========================================
- Coverage   77.29%   59.08%   -18.21%     
===========================================
  Files         255      255               
  Lines       33641    33645        +4     
===========================================
- Hits        26002    19879     -6123     
- Misses       7639    13766     +6127

Impacted Files	Coverage Δ
datalad/interface/utils.py	75.47% <86.66%> (-0.6%)	⬇️
datalad/interface/tests/test_save.py	16.3% <0%> (-83.7%)	⬇️
datalad/ui/tests/test_base.py	16.66% <0%> (-83.34%)	⬇️
datalad/distribution/tests/test_dataset.py	17.6% <0%> (-82.4%)	⬇️
datalad/metadata/tests/test_aggregation.py	17.84% <0%> (-81.23%)	⬇️
datalad/distribution/tests/test_siblings.py	19.14% <0%> (-80.86%)	⬇️
datalad/distribution/tests/test_dataset_binding.py	19.23% <0%> (-80.77%)	⬇️
datalad/interface/tests/test_base.py	19.48% <0%> (-80.52%)	⬇️
datalad/interface/tests/test_diff.py	22.03% <0%> (-77.97%)	⬇️
datalad/interface/tests/test_ls_webui.py	15.5% <0%> (-77.31%)	⬇️
... and 105 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update ebb8b93...4601749. Read the comment docs.

[kyleam]

The additional parameter is fine by me, though I have a slight preference for just defining proc_cfg above _get_procedure_specs.

[yarikoptic]

that is how I did it first, but then it should be not a pure variable since you can't rebind it inside, but some kind of a container (I had list). Just looks ugly etc, so decided to make it explicit

[yarikoptic]

no travis report here, but it is there and I seems screwed up

1114======================================================================
1115ERROR: datalad.distribution.tests.test_create.test_create_withprocedure
1116----------------------------------------------------------------------
1117Traceback (most recent call last):
1118  File "/home/travis/virtualenv/python2.7.15/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
1119    self.test(*self.arg)
1120  File "/home/travis/virtualenv/python2.7.15/lib/python2.7/site-packages/datalad/tests/utils.py", line 615, in newfunc
1121    return t(*(arg + (filename,)), **kw)
1122  File "/home/travis/virtualenv/python2.7.15/lib/python2.7/site-packages/datalad/distribution/tests/test_create.py", line 320, in test_create_withprocedure
1123    proc_post=[['cfg_metadatatypes', 'xmp', 'datacite']])
1124  File "/home/travis/virtualenv/python2.7.15/lib/python2.7/site-packages/datalad/interface/utils.py", line 399, in eval_func
1125    proc_cfg=proc_cfg)
1126ValueError: need more than 1 value to unpack

so will fix it now

[kyleam]

so will fix it now

I've already fixed it in fe9bff6.

Edit: Travis is just starting to run for that push here.

[kyleam]

so will fix it now

I've already fixed it in fe9bff6.

Sorry, ignore me. I fixed another error that the initial commit caused in test_run_procedure, but it looks like this is a different source.

[yarikoptic]

then I guess there more! I should have indeed went the "outside variable" way to make it less fragile :-/

$> git show                                        
commit 4601749db64e9d0e45b81b68f8086f9feb422d4c (HEAD -> opt-doitonce)
Author: Yaroslav Halchenko <debian@onerussian.com>
Date:   Fri Aug 2 09:42:04 2019 -0400

    BF: eval_func: One more fix to return value

diff --git a/datalad/interface/utils.py b/datalad/interface/utils.py
index ea510f598..0a169aaae 100644
--- a/datalad/interface/utils.py
+++ b/datalad/interface/utils.py
@@ -369,7 +369,7 @@ def eval_results(func):
             spec = common_params.get(param_key, None)
             if spec is not None:
                 # this is already a list of lists
-                return spec
+                return spec, proc_cfg
 
             if not proc_cfg:
                 # .is_installed and .config can be costly, so ensure we do
changes on filesystem:                                                                                                                                                                                                            
 .asv | 0
(dev) 1 15626.....................................:Fri 02 Aug 2019 09:50:14 AM EDT:.
(git)hopa:~datalad/datalad[opt-doitonce]git
$> git range-diff gh-yarikoptic/opt-doitonce...HEAD
-:  --------- > 1:  4601749db BF: eval_func: One more fix to return value

why range-diff doesn't show the diff? here is no rewrite but a new commit

pushing

[kyleam]

why range-diff doesn't show the diff? here is no rewrite but a new commit

range-diff won't show the diff for added or dropped commits, only those for matched patches, which means it's not particularly useful (or needed) when you're not rewriting a series.

[kyleam]

commit 4601749db64e9d0e45b81b68f8086f9feb422d4c (HEAD -> opt-doitonce)
Author: Yaroslav Halchenko <debian@onerussian.com>
Date:   Fri Aug 2 09:42:04 2019 -0400

    BF: eval_func: One more fix to return value

diff --git a/datalad/interface/utils.py b/datalad/interface/utils.py
index ea510f598..0a169aaae 100644
--- a/datalad/interface/utils.py
+++ b/datalad/interface/utils.py
@@ -369,7 +369,7 @@ def eval_results(func):
             spec = common_params.get(param_key, None)
             if spec is not None:
                 # this is already a list of lists
-                return spec
+                return spec, proc_cfg

Looks good. I missed that in my fixup commit.