Add number of allocations to time/timed macros, fix realloc calculations

[ScottPJones]

This adds counting of the number of allocations to @time and @timed (@timed also now returns the number of frees, and reallocs).
It also fixes a bug that happens if you use realloc to shrink the size of something, it would subtract from allocd_bytes, instead of adding to freed_bytes.

[StefanKarpinski]

This seems like a reasonable way to do this for now, but it might be good in the future to refactor things so that there are fewer tiny functions to get info about allocations. Maybe a struct that can be returned.

[carnaval]

You are not counting pool allocations, which are 99% of the workload in most cases. It is not strictly a malloc call but I think people would expect it to be taken into account.

I'm not sure that the number of free calls is very informative for the same reason. We could expose the number of freed objects instead but it requires a bit of addtional bookeeping in the pool sweeping. I mostly (perhaps cowardly) don't want people trying to second guess the gc heuristics and argue to change them. The number of allocation only depends on your code whereas the number of freed objects depends a lot on the gc's decisions.

[carnaval]

@StefanKarpinski agreed

[ScottPJones]

@StefanKarpinski Very good point, I was just following what was there before... refactoring would be nice... I wanted to refactor timed / time, but I'm not sure how (yet) with macros... more investigation!

[ScottPJones]

@carnaval I was just changing the places where allocd_bytes was being updated... I missed this pooled allocation? If you can point me where to fix it, I will, thanks!

[carnaval]

https://github.com/JuliaLang/julia/blob/master/src/gc.c#L1030

[carnaval]

I think the number of allocation could use a little pretty printing since it is likely to get very large, as you will probably experience once you add the pool stuff.

[ScottPJones]

@carnaval I ended up splitting up the display of malloc/realloc/pool, they have very different performance characteristics (realloc may mean copying, etc.). Is there a nice function already to get "K","M","G" to display counts prettily? Thanks!

[StefanKarpinski]

I really think this is getting out of hand. It would be fine if we provide a way or getting this info for those who really need to know, but this is way too much info to display by default.

[ScottPJones]

@StefanKarpinski Adding the number of allocations was from @vtjnash 's suggestion on julia-users.
I found a lot of value in seeing the information about allocations, it was actually more useful than the raw amount allocated for what I was doing, however, since I've added the information to the @timed macro, I assume someone could easily print out just the pieces they are interested in using that. I can remove the extra display from @time, if that's what everybody (or the majority) want.

[StefanKarpinski]

I'm fine with the number of allocations, but separating out the number of reallocs is too much. And what is this "pool" value? Displaying it with slashes between means there's zero chance that someone can understand what's going on just from reading the output of @time.

[ScottPJones]

So, would you have mallocs+reallocs, or mallocs+reallocs+pool, displayed as a single number in @time? The pool allocations are ones that are handled without having to resort to a C malloc call.
reallocs of course are interesting to see if you have code that is allocating an array and growing it, instead of allocating it once, part of what I changed to speed things up for UTF conversions... but I'm happy just getting them separately from @timed.

[StefanKarpinski]

I don't know, but this is too much information. We should either display a multiline detailed output here that's clear and readable or introduce another mechanism for getting this information. I suspect that returning a struct from @timed would be a good idea – this can be the same shape of struct that the C code uses to collect the data. It can even be made iterable to avoid breaking old code.

[ScottPJones]

@timed just returns a tuple, I simply added extra values at the end... would returning the information as a structure definitely be better? (I'm happy to do it however, just want the functionality available...)

[StefanKarpinski]

I made that comment at the point where you were also printing all the information. I do think that returning a structure might be more reasonable at this point. Returning that many values from a function is getting unwieldy.

[carnaval]

I agree with Stefan. I think a summary of total_number_of_alloc_events and total_size_allocated is sufficient. I don't think we have a facility for big number formatting in Base.

I'm not convinced by the realloc argument. I'm not against providing it as a separate function but I think just having the summary is what people need. Remember that a lot of people are using @time for actual timing and the GC details are not of interest to them (well except when it's the bottleneck I guess).

[carnaval]

Minor style nitpick but could you rename those counters to num_ instead of cnt_ (just for consistency with the rest, even if admittedly there are many inconsistent naming in there). I also think that num_pool_alloc is clearer than num_pool. Thanks !

[ScottPJones]

All good stuff everyone! I'm trying to get this done ASAP so I can get back to some "real" work 😀
@StefanKarpinski I'll put it in a structure, no problem, for coming back from C, do you want @timed to also return the structure? Currently it returns a tuple, I don't want to break anybody who uses it... should I just add the structure as the last value in the tuple?
@carnaval Yes, I'd meant to do that... but, if you look at the number of issues I've made (and am trying to fix myself), I slipped up! Will do (cnt -> num). reallocs are only returned in @timed now, not displayed in @time.

[ScottPJones]

Help! I must have messed things up with Git! This is only supposed to be 3 files! I updated it to remove a trailing space on one line... and now... 😢

[pao]

Oooh. Got a merge. Nasty. The following is not recommended, but is also exactly what I'd do to fix.

git branch pao-broke-my-repository # always good to make a backup of your current situation
git reset --hard b7f9286 # note any changes not checked in will be lost
git cherry-pick a3d8a1c # but we do want that whitespace fixed

[ScottPJones]

@pao You are a real lifesaver! That looks like it did the trick, thanks!

[ScottPJones]

Any reason this cannot be merged in? I believe I've addressed all of the requests for changes.
Thanks, Scott

[tkelman]

Anywhere that we have a struct in C and a type in Julia that need to be kept exactly in sync, it would be good to mark both with a comment pointing to the other - "If you change this, be sure to make the corresponding change in ____"

[ScottPJones]

OK, very good point! Will add that now... anything else?

[tkelman]

Whoops, didn't notice this at first, but speaking of keeping them in sync, is it just me or are the last 3 elements in different orders?

[ScottPJones]

@tkelman Thanks very much for catching that! I need more sleep or more caffeine before I commit stuff!

[carnaval]

Last few points, then I think you can squash and this is good to go :

• could you make the struct immutable ? It will require making a new one in the diff function. It may be stupid but I don't like the idea of allocating gc memory in a place where we are measuring it. Making it immutable will make this not hit the gc at all.
• I think the wording can be made more compact like "bla allocations (blu MB)" instead of repeating allocated
• it will be quickly unreadable if you don't pretty print the number of allocation events, this can go to billions easily

[ScottPJones]

OK, all good points. About making the struct immutable, doesn't that mean you'd always have to do an allocation, instead of just allocating 2 structs at the beginning of a loop (if you are reporting the differences in a loop)? I'm still learning all the ins and outs of optimizing Julia for mem allocations...
I also had wondered about getting rid of the repeated "allocations" "allocated", your idea looks good. Thanks!

[carnaval]

If a type is immutable and known to the compiler without ambiguities (which is very likely to be the case here) it is passed around by copies and never uses dynamic memory allocation. The only case where we do allocate memory for such objects is when it must be passed to code which may not be aware of the type in advance and require boxing it.

[ScottPJones]

Note: when I compare this branch to Julia, it only shows my commits...

[tkelman]

The idea is you want just 7582922, yes? I suspect you had everything right until you tried to do a push, which complained and made you do a merge - the merge commit is where things get messy and you don't want to include those here.

Try the following

git checkout -b spj/time2 # save the current state to a new branch
git branch -D spj/time # delete existing messy copy
git checkout master
git checkout -b spj/time # make a new clean branch with the same name
git cherry-pick 7582922a5c82de9a6ccd6e4bd51b4c34b02b24d8 # add in the one commit you want
git push origin +spj/time # do a *force push* (marked by the + before the branch name) to overwrite the branch's contents with a hopefully clean replacement

you may need to use a different remote name than origin, depending what remote you have your fork under

[ScottPJones]

Thanks, is that correct now? I've put some examples on Gist:
https://gist.github.com/ScottPJones/e7c38085a3c391578261
https://gist.github.com/ScottPJones/bb712f7b85d1d8d91a9a#file-results-from-v-0-4-time

[tkelman]

It's only one commit now which is good, you tell me if it has all the changes you wanted.

One superficial thing is it looks like you've got some mixed tabs and spaces, we try to avoid tabs everywhere except in makefiles, 4-space indent is preferred for the C and Julia code in src and base.

[ScottPJones]

Sorry about the tabs... I keep resetting the "smart-tabs" variable in the editor, and writing out the state, but it's like a zombie, it keeps coming back! I did do 4-space indents everywhere (that's also what we came up with where I'm consulting)

[ScottPJones]

Do I need to squash this puppy again? 😀

[jakebolewski]

yes

[ScottPJones]

The puppy is all squished! 🐶

[tkelman]

Anyone else think getunits and printnz are somewhat likely to collide with future names that we may want to use elsewhere? Maybe not such a big deal since they're not exported from Base, but any future additions where those names would be natural to use will have to be aware of these methods.

And sorry to nitpick, but the couple times in the C code where you're using code like this

if (sz < old) freed_bytes += (old - sz);
else allocd_bytes += (sz - old);

could use some newlines and indenting to fit with the code style elsewhere.

[ScottPJones]

@tkelman As I've said before, I greatly appreciate all constructive criticism. I'll change the formatting of the bug fixes with reallocs. I just noticed the bugs and fixed them quickly, and 35 years of the style I've become accustomed to came out of my fingers without thought! About the names, I'll change those
(do you have any suggestions?), but that actually brings up a major problem I have with Julia... it seems there is no way to keep your abstraction and implementation separate, and keep voyeurs from looking at your private parts, or indeed from playing with them... and everybody is also very exhibitionist... letting stuff that should stay private getting seen in public... CLU was the best language I knew in that regard...

[tkelman]

it seems there is no way to keep your abstraction and implementation separate [might want to edit the rest of this sentence to be slightly less colorful]

Right, there have been a few conversations around this, and other than sometimes sort-of following some of the Python convention of underscore-oriented-programming (which some people understandably dislike), I don't think we have a great solution for this yet. At least the convention is generally towards extension via methods and dispatch rather than monkey-patching the way Ruby and Python code often does.

Shipping hidden proprietary code written in Julia will probably have to be done by AOT compilation into shared libraries. Not sure whether there will be any better solutions but it's worth thinking about.

[ScottPJones]

I'm not concerned so much about shipping hidden proprietary code, but rather software engineering practices. I've seen too many times what happens when customers start playing around directly with your implementation, and then you can be locked into that implementation forever (even if it sucks!).
Just like immutable keeps things from being modified, you need something to keep something private, so that you can't cause namespace pollution, or have to pick ugly long names to avoid it, which seems to be what is being suggested here for getunits and printnz.

[ScottPJones]

OK, please look at this again... I changed the names to prettyprint_getunits & padded_nonzero_print,
and changed the C code... (just saying, that style was prohibited in the C style guide I wrote! 😀
Our guide said that if the statement was not on the same line as the if/else/else if, then it needed { }.)

[ScottPJones]

OK... any hope of getting it merged? 😀 Thanks for all the comments!

[tkelman]

I think this is good enough to merge for now, we can keep tweaking it on master. Could do with some tests eventually, for one thing (but I don't think we have any for these macros now, so this isn't really making things any worse).

[ScottPJones]

Thanks! I’m not sure how you’d test a macro like this... @timed maybe, where it returns the information instead of printing it... if anyone has a suggestion, I’ll certainly add testing...

[yuyichao]

@ScottPJones The time seems to be printed twice for @timev, is this intentional?

[ScottPJones]

Yes, the first line is the pretty printed value, exactly the same as @time, after that, it prints out the raw information that it collects, not rounded or anything...

[tkelman]

We do still need docs for the new @timev macro.

[ScottPJones]

Ah! Yes, that slipped between the cracks... will do (must be that early onset Alzheimers!)