Strange results with --track-allocation=all

[Scott Jones]

I was trying to figure out why I'm still getting many more allocations that I'd thought the conversion process would have... and was told to try --track-allocation.

However, it seems a bit difficult:

1) Many .mem files are output that have no memory allocations,  they just have a 0 instead of a - before the code.

2) Weird results like the following:

ScottsRetinaMBP:julia scott$ usr/bin/julia --track-allocation=all

               _

   _       _ _(_)_     |  A fresh approach to technical computing

  (_)     | (_) (_)    |  Documentation: http://docs.julialang.org

   _ _   _| |_  __ _   |  Type "help()" for help.

  | | | | | | |/ _` |  |

  | | |_| | | | (_| |  |  Version 0.4.0-dev+4878 (2015-05-17 14:02 UTC)

 _/ |\__'_|_|_|\__'_|  |  integration/140fc65* (fork: 8 commits, 0 days)

|__/                   |  x86_64-apple-darwin14.4.0

julia> a = "a\uff\u800\uffff\U10ffff"

"aÿࠀ\uffff\U10ffff"

julia> Profile.clear_malloc_data()

julia> utf16(a)

"aÿࠀ\uffff\U10ffff"

julia> exit()

        - function reencode_string_8_16(str::Vector{UInt8})

  6037092     len::UInt = sizeof(str)

        -     # handle zero length string quickly

        0     if len == 0

        0         buf = Vector{UInt16}(1)

        0         buf[1] = 0

        0         return UTF16String(buf)

        -     end

        -     # Check that is correct UTF-8 encoding and get number of words needed

        0     len, cnt2::UInt, cnt3::UInt, cnt4::UInt, flags::UInt = check_string_utf8(str)

        -     # Optimize case where no characters > 0x7f

        0     flags == 0 && return reencode_string_a_16(str)

        0     len += cnt4

       80     buf = Vector{UInt16}(len+1)

I certinally hope that simply getting the *size* of a vector into an unsigned variable doesn't cause 6MB to be allocated!

[Tim Holy]

Anything that gets called from the REPL will be "credited" with all the
allocation that occurs in the REPL: it works by asking "how many bytes were
allocated since the last compiled line of code ran?" Since many things typed
into the REPL are interpreted, they can add allocations that get assigned to
the wrong place.

Coverage.jl has some tools to help you sort lines by the number of bytes
allocated, across all the files in a directory.

--Tim

[Scott Jones]

What about the line that had: `6037092     len::UInt = sizeof(str)`

That just seems like it is a bug, to me...

[Tim Holy]

Two possibilities:
- It's a false alarm. Since that's the first line of the function, it is
getting blamed for allocations that occurred in the caller. I was assuming
that caller was the REPL, but since I don't know how you called this that
could easily be wrong. In that case, there may indeed be some bug (or at
least, something that I don't understand) in the tracking algorithm.
- sizeof(str) is not type-stable. The fact that there's the ::UInt on the len
supports that hypothesis. len::UInt = foo() doesn't prevent the allocation if
foo() is unstable, but it does prevent the consequences from "cascading" to
later lines.

@code_warntype should be your friend here, if you know the type of str.

--Tim

[Scott Jones]

sizeof(str) is not type-stable?  I would have thought that it would always return something like a UInt64 (size_t for the C/C++ people)...

Thanks,

Scott

[Tim Holy]

Looking over your post again: I see you are calling this from the REPL, so my
first hypothesis was right. In particular, you need to warm up (JIT-compile)
the utf16 function before you call Profile.clear_malloc_data(). You're surely
measuring the memory allocated during compilation. Even if you do warm it up,
you're likely to see a spurious allocation on the first line of whatever gets
directly called from the REPL. It can be confusing because of inlining, so to
really avoid confusion try

@noinline wrapper(a) = utf16(a)


Of course, the fact that you've got one confound doesn't rule out type-
instability in sizeof. Since I'm not on your branch, how about you just check
it directly with @code_warntype utf16(a) rather than asking me? :-)

--Tim

[Scott Jones]

Body:

  begin  # utf16.jl, line 505:

      GenSym(15) = sizeof(str::Array{UInt8,1})::Int64

      len = box(UInt64,check_top_bit(GenSym(15))) # line 507:

      unless box(Bool,and_int(sle_int(0,0)::Bool,len::UInt64 === box(UInt64,0)::Bool)) goto 0 # line 508:

I wasn't aware of `@code_warntype`  (I've only been programming in Julia for a bit over a month, and even poring over the documentation every spare moment, I haven't been able to memorize it all (yet!).

Thanks for that suggestion, it is very useful!  It does look like the problem has to do with me expecting sizeof() to return an unsigned value like C, but here it says it returns an Int64...

(what does a negative size even mean?)

I still think that reporting millions of bytes of allocation, *after* I supposedly cleared that info with `Profile.clear_malloc_data()` looks like a bug...

Scott

[Tim Holy]

On Sunday, May 17, 2015 07:24:09 PM Scott Jones wrote:
> I wasn't aware of `@code_warntype` (I've only been programming in Julia
> for a bit over a month, and even poring over the documentation every spare
> moment, I haven't been able to memorize it all (yet!).

It was also mentioned in my earlier message in this thread, but it's indeed
easy to miss such things.

> I still think that reporting millions of bytes of allocation, *after* I
> supposedly cleared that info with `Profile.clear_malloc_data()` looks like
> a bug...

You had never called `utf16(a)`, and consequently it had to compile that
function. _After_ your call to clear_malloc_data. So the blame for some large
fraction of the memory needed to compile the function got put in a place that
(justifiably) seems weird.

--Tim

[Yichao Yu]

This is exactly why I always call the function once and then run a
full GC before doing any benchmark.... Is there any functions/macros
that does this? (I end up just copying my function into all my
benchmarks but maybe it is generically useful as well?)

>
> --Tim
>

[Milan Bouchet-Valat]

Le dimanche 17 mai 2015 à 19:24 -0700, Scott Jones a écrit :

Body:

  begin  # utf16.jl, line 505:

      GenSym(15) = sizeof(str::Array{UInt8,1})::Int64

      len = box(UInt64,check_top_bit(GenSym(15))) # line 507:

      unless box(Bool,and_int(sle_int(0,0)::Bool,len::UInt64 === box(UInt64,0)::Bool)) goto 0 # line 508:

I wasn't aware of `@code_warntype`  (I've only been programming in Julia for a bit over a month, and even poring over the documentation every spare moment, I haven't been able to memorize it all (yet!).

Thanks for that suggestion, it is very useful!  It does look like the problem has to do with me expecting sizeof() to return an unsigned value like C, but here it says it returns an Int64...

(what does a negative size even mean?)

Indeed, that's a logical expectation for people coming from C (like you and me). Stefan has addressed this question here:
https://groups.google.com/d/msg/julia-users/RX8sFQHvEV4/PgfJ7JoVin8J


Regards

[Scott Jones]

I may have to update the section of the documentation I added, about Noteworthy differences... this one worked, but causes an unexpected performance penalty...

(A C/C++ programmer would normally think of using an unsigned value, precisely to improve performance... where here it seems to be the opposite, because of the boxing going on...)

[Yichao Yu]

On Mon, May 18, 2015 at 8:54 AM, Scott Jones <scott.pa...@gmail.com> wrote:
> I may have to update the section of the documentation I added, about
> Noteworthy differences... this one worked, but causes an unexpected
> performance penalty...
> (A C/C++ programmer would normally think of using an unsigned value,
> precisely to improve performance... where here it seems to be the opposite,
> because of the boxing going on...)

I think the compiler is smart enough to omit those boxing. Have you
checked code_llvm and see there's really boxing going on? (following
is my simple test)

P.S. personally what I usually do to figure out whether there's any
allocation going on is simply running @code_llvm and look for gc frame
and alloc* function calls :P

```julia
julia> function f(str)
l::UInt = sizeof(str)
return l + 1
end
f (generic function with 1 method)

julia> @code_llvm f(Int8[])

define i64 @julia_f_44546(%jl_value_t*) {
top:
%1 = call i64 @julia_sizeof1541(%jl_value_t* %0)
%2 = icmp sgt i64 %1, -1
br i1 %2, label %pass, label %fail

fail: ; preds = %top
%3 = load %jl_value_t** @jl_inexact_exception, align 8
call void @jl_throw_with_superfluous_argument(%jl_value_t* %3, i32 2)
unreachable

pass: ; preds = %top
%4 = add i64 %1, 1
ret i64 %4
}

julia> @code_typed f(Int8[])
1-element Array{Any,1}:
:($(Expr(:lambda, Any[:str],
Any[Any[:l],Any[Any[:str,Array{Int8,1},0],Any[:l,UIn
t64,18]],Any[],Any[Int64]], :(begin # none, line 2:
GenSym(0) = sizeof(str::Array{Int8,1})::Int64
l = (top(box))(UInt64,(top(check_top_bit))(GenSym(0))) # line 3:
return (top(box))(UInt64,(top(add_int))(l::UInt64,(top(box))(UInt64,(top(c
heck_top_bit))(1))))
end::UInt64))))

```

[Yichao Yu]

On Mon, May 18, 2015 at 10:34 AM, Yichao Yu <yyc...@gmail.com> wrote:
> On Mon, May 18, 2015 at 8:54 AM, Scott Jones <scott.pa...@gmail.com> wrote:
>> I may have to update the section of the documentation I added, about
>> Noteworthy differences... this one worked, but causes an unexpected
>> performance penalty...
>> (A C/C++ programmer would normally think of using an unsigned value,
>> precisely to improve performance... where here it seems to be the opposite,
>> because of the boxing going on...)
>
> I think the compiler is smart enough to omit those boxing. Have you
> checked code_llvm and see there's really boxing going on? (following
> is my simple test)

OK there's probably a overflow/sign check or sth like that, which
might be good to avoid, but isn't very bad anyway...