Make imagemetadata easier to debug.

Make imagemetadata easier to debug.

I'm losing a lot of time to debugging imagemetadata/simplestreams interaction for the Azure provider, and the format for Azure's simplestreams entries is changing.  (There was an irregularity in the format that stopped imagemetadata from finding any matches at all for Azure).  The usual failure mode is simply that no images are found, which gives me very little information to work with.

To make all this a little easier, I added debug logging (yes, using loggo) to suspicious results.  Some of the code had to be restructured a bit to make suspicious conditions more explicit, where previously they were implicit outcomes of complex loops.  The loops were really "extract; filter; process" sequences.  Much simpler than the code looked.  Loop fission brought this out nicely, and also made suspicious results come out more obviously in the code.  Some of the error strings came out a little bit more specific as well.

I touched the imports on the test.  I grouped them in the new way.  But if you're going to ask me to rename the gocheck import to "gc," then please be patient until I have two reviews!  It wouldn't be polite to pollute the diff like that for the next reviewer, and it might lead to conflicts while waiting for the second review.

https://code.launchpad.net/~jtv/juju-core/imagemetadata-debug-logging/+merge/179141

(do not edit description out of merge proposal)

[jtv.canonical, 2013-08-08 10:00:12]

Please take a look.

[dimitern, 2013-08-08 11:11:52]

LGTM, just a few suggestions.

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
File environs/imagemetadata/simplestreams.go (right):

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:244: // match function returns "true." 
It preserves order.

Perhaps, just: s/"true."/true.

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:293: logger.Infof("cannot load index
%q/%q: %v", baseURL, indexPath, err)

This should be a Warningf or an Errorf, I think.

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:301: logger.Infof("skipping index %q/%q:
%v", baseURL, indexPath, err)

See above.

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:378: func(metadata *indexMetadata) bool
{ return metadata.DataType == imageIds })

Please, split this on multiple lines:
candidates = candidates.filter(
    func(metadata *indexMetadata) bool {
        return metadata.DataType == imageIds
    }
)

[rog, 2013-08-08 11:16:10]

Nice - it will be great to have more
insight into what's going on here.

One thought: should these messages perhaps
be logged at Debug level rather than Info level?

LGTM modulo a few suggestions below.

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
File environs/imagemetadata/simplestreams.go (right):

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:212: result := indexMetadataArray{}
result := make(indexMetadataArray, 0, len(ind.Indexes))

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:241: type indexMetadataArray
[]*indexMetadata

s/Array/Slice/

("array" means something slightly different in Go)

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:245: func (entries indexMetadataArray)
filter(match func(*indexMetadata) bool) indexMetadataArray {
Alternatively, to save garbage (and given that all calls are
of the form x = x.filter(...):

// filter deletes all entries for which match returns false.
func (entriesPtr *indexMetadataArray) filter(match func(*indexMetadata) bool) {
    entries := entriesPtr
    dest := 0
    for i, metadata := range entries {
        if match(metadata) {
            entries[dest] = metadata
            dest++
        }
    }
    *entriesPtr = entries[0:dest]
}
}

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:301: logger.Infof("skipping index %q/%q:
%v", baseURL, indexPath, err)
"skipping index because of error getting latest metadata %q/%q: %v"

?

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:394: // Pick arbitrary match.

Perhaps at a slightly less important debugging level, it might
be nice to print all the candidates here, so we can see
the possibilities.

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:615: availableProducts := []string{}
availableProducts := make([]string, 0, len(imageMetadata.Products))

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams.go:624: var bv byVersionDesc =
make(byVersionDesc, len(catalog.Images))
bv := make(byVersionDesc, 0, len(catalog.Images))
and then use append below, avoiding the need for i.

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
File environs/imagemetadata/simplestreams_test.go (right):

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
environs/imagemetadata/simplestreams_test.go:409: (array[0] ==
ind.Indexes["foo"]),

You can lose some brackets here and below.

[jtv.canonical, 2013-08-08 11:23:13]

Thanks for the very fast review!

On 2013/08/08 11:11:52, dimitern wrote:

https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:244: // match function returns "true."

> It preserves order.
> 
> Perhaps, just: s/"true."/true.

OK.  Changed.


https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:293: logger.Infof("cannot load index
> %q/%q: %v", baseURL, indexPath, err)
> 
> This should be a Warningf or an Errorf, I think.

I suppose it's not an error if the code deliberately doesn't treat it as an
error...  I'll meet you halfway and make it Warningf.


https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:301: logger.Infof("skipping index
%q/%q:
> %v", baseURL, indexPath, err)
> 
> See above.

Done.


https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:378: func(metadata *indexMetadata)
bool
> { return metadata.DataType == imageIds })
> 
> Please, split this on multiple lines:
> candidates = candidates.filter(
>     func(metadata *indexMetadata) bool {
>         return metadata.DataType == imageIds
>     }
> )

I had that originally, but there was one problem: to someone scanning the code
(as opposed to someone reading this one function intently), the "return"
statements in those nested functions looked a lot like returns from the outer
function.

So I changed it a bit more: I have now broken them up like you say, but I no
longer define them inside the argument list.  I define them as variables first.

[jtv.canonical, 2013-08-08 13:20:18]

On 2013/08/08 11:16:10, rog wrote:
> Nice - it will be great to have more
> insight into what's going on here.

Thanks to you too, particularly for reviewing this so quickly.


> One thought: should these messages perhaps
> be logged at Debug level rather than Info level?

Funny: Dimiter just asked me to raise some debug levels.  :)  I have no strong
opinions here, and as you say maybe we should just see what additional insight
this gives us.  If there's unwanted output, we can reduce some of these levels.


>
https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:212: result := indexMetadataArray{}
> result := make(indexMetadataArray, 0, len(ind.Indexes))

If you like.  I doubt it'll make much difference for performance, after the http
requests and the json parsing.  Know your Amdahl's Law.  :)  Also, given that
these are all four-to-the-bar regular loops based on built-ins, AFAICS a good
compiler may well have all the information it needs to figure out the length for
itself at the top of the loop.  If it doesn't do that yet, chances are it's
because it's not enough of a priority.


>
https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:241: type indexMetadataArray
> []*indexMetadata
> 
> s/Array/Slice/
> 
> ("array" means something slightly different in Go)

You're right, technically it's a slice.  Changed.


>
https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:245: func (entries indexMetadataArray)
> filter(match func(*indexMetadata) bool) indexMetadataArray {
> Alternatively, to save garbage (and given that all calls are
> of the form x = x.filter(...):

Remember Kernighan's Law.  Clever code isn't so hard to come up with -- it's
just an admission of defeat in producing something simpler.  But cleverness can
be very hard to debug.  In-place alteration for instance easily leads to nasty
surprises.  My version goes for the lower maintenance risk; yours goes for
higher speed.

Now apply Knuth's Law.  The big problem with this package is that the code is
unclear, not that expanding small arrays is slow.

At this point you might argue that the optimization doesn't do *much* harm and
yet it might be imperceptibly faster, for almost free.  But do you even know
that the optimization doesn't accidentally make things worse, on current or
future compilers?  For starters, far as I can see my version could be giving the
compiler all the information it needs to produce your version -- *if* the
developers determine that it's an improvement.  There are other ways in which
the optimized version could accidentally do worse than the naive version:
register allocation becomes more conservative (and loads have trouble moving
before stores) when aliasing can't be figured out statically.  Cache access
patterns could get better or worse, depending on lots of factors, and those are
*lots* of fun to figure out.  And what about branch misprediction rates?  I'm
not saying that your version is slower, just that human intuitions are
notoriously poor in this field, compilers are a lot smarter than they used to
be, and you're a lot better off leaving well enough alone.


>
https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:301: logger.Infof("skipping index
%q/%q:
> %v", baseURL, indexPath, err)
> "skipping index because of error getting latest metadata %q/%q: %v"
> 
> ?

OK.  Changed.


>
https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:394: // Pick arbitrary match.
> 
> Perhaps at a slightly less important debugging level, it might
> be nice to print all the candidates here, so we can see
> the possibilities.

Good one.  That may help me immediately with my debugging.


>
https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:615: availableProducts := []string{}
> availableProducts := make([]string, 0, len(imageMetadata.Products))

Hmm... not actually useful but not *much* harder to read, so if you prefer, I'll
change it.


>
https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams.go:624: var bv byVersionDesc =
> make(byVersionDesc, len(catalog.Images))
> bv := make(byVersionDesc, 0, len(catalog.Images))
> and then use append below, avoiding the need for i.

I'm beginning to wonder what the purpose of all these array-tweaking comments
is.  Twenty years ago we worried about these things; the most important thing
that faster hardware and better compilers have bought us since is the ability to
write simple code quickly, and optimize afterwards where effective.  On modern
PC-range systems, if I can make the code slightly clearer at the cost of a few
thousand CPU cycles per minute, outside of latency-critical code, I take that as
a clear win.  Even when it *is* latency-critical, sometimes the really effective
optimization is just hidden from view by these low-level distractions.

So asking for all these poorly-justified changes looks a lot like bikeshedding
for the sake of it.  It's a culture that I've seen do a lot of harm to projects,
and not all that much good.  I implemented almost all of your changes, but if I
hadn't, are they good enough that you'd go back and make them yourself?  If so,
ask yourself why.



>
https://codereview.appspot.com/12655043/diff/1/environs/imagemetadata/simples...
> environs/imagemetadata/simplestreams_test.go:409: (array[0] ==
> ind.Indexes["foo"]),
> 
> You can lose some brackets here and below.

I know, thanks.  They're not just here for the compiler -- they're here as a
convenience for the reader.  Especially when readers may be familiar with
multiple programming languages, and don't want to specialize their reading
skills to the point where small differences in precedence tables become assumed
knowledge.  This isn't as esoteric as it sounds: I've seen real bugs happen
because of these things.