Monitor asset build time

[Louis-Backstrom]

I've been thinking it might be useful to have a measure of how long each stage of the asset build takes. In my personal projects I've been using the package tictoc, which provides handy ways to time each section of code and print for the user to interpret - it might be possible to do more with it too, I haven't really dug into it. I think it's pretty lightweight too so shouldn't slow down the builds noticeably.

Does this sound like a useful addition?

[jeffreyhanson]

Sounds great! How urgent is this? I'm a bit busy at the moment so I probably won't have much time to work on non-critical stuff for a few weeks. I haven't used that package before to time stuff, so if you'd like to have a go at adding the timings then that would be awesome? The main script for creating the assets is: code/scripts/create_assets.R

[Louis-Backstrom]

I've just pushed a commit that will hopefully achieve something close to what I had in time. Haven't had the chance to test it in vivo yet but it works on a small scale in RStudio. Two questions for @jeffreyhanson though -

1. Do I need to do anything more than library(tictoc) at the start of the file to ensure the package is loaded? Given that this is a new package for the project, should there be a require() or install.packages() somewhere? Or does it need to be added to the build image?

2. I note that for all functions that come from non-base packages (e.g. dplyr) you've explicitly called them in the package::function() format rather than just function() - I've done the same (or tried to) - is it necessary or just good practice?

[jeffreyhanson]

Great!

1. In order to use tictoc, we need to add the package to the atlas' build environment (https://github.com/bird-team/build-env). I'll try and sort that out today and let you know when its ready. After that, you'll need to pull the latest version of the build environment (using make rm_image pull_image).

2. Yes, please use the package::function() format. It's not necessary if you use library(package), but I consider it good style because you're telling R exactly what function you want to use. Since multiple packages can have different functions that are assigned the same name, you can get into trouble sometimes if you don't specify exactly what function you use from which package. By using this format, it means things are less likely to go wrong if you need to use extra packages in your code.

[Louis-Backstrom]

Okay brilliant - thought that was the case. Will remember both of those in future - trying to teach myself R at the moment (for uni but also for stuff like this) so expect to see me digging around in the code a bit more!

[jeffreyhanson]

Awesome!! The atlas build environment has been successfully rebuilt with the tictoc R package added it, so if you grab the new version (i.e. make rm_image pull_image command) you should be able to remake the assets with the timings.

[Louis-Backstrom]

Okay, just tried to remake assets. Took me a couple of attempts to iron out some problems with the tictoc code but in theory it should be working now. Only problem is it doesn't seem to be showing at the end of the process like I want it to:

  inflating: surveyor-sheets/grid-10351-dutton-park.pdf
 extracting: surveyor-sheets/grid-10330-wakerley.hash
  inflating: surveyor-sheets/grid-10502-rochedale-south.pdf
  inflating: surveyor-sheets/grid-10328-tingalpa.pdf
 extracting: surveyor-sheets/grid-9191-tailor-bight.hash
 extracting: surveyor-sheets/grid-10545-glider-forest-west.hash
 extracting: surveyor-sheets/grid-10445-karalee.hash
  inflating: surveyor-sheets/grid-10394-ugly-gully.pdf
 extracting: surveyor-sheets/grid-10470-moggill-east.hash
 extracting: surveyor-sheets/grid-10397-huntingdale.hash
  inflating: surveyor-sheets/grid-10014-fitzgibbon.pdf
 extracting: surveyor-sheets/grid-9101-north-west-beach.hash
 extracting: surveyor-sheets/grid-10325-balmoral.hash
  inflating: surveyor-sheets/grid-10517-sunnybank-hills-south.pdf
 extracting: surveyor-sheets/grid-10317-gap-creek-south.hash
bba
bba

This is the end of running make assets - I'd like it to print the times for each clock at the end (or between the extracting and bba lines) but it isn't - does the extracting/inflating part happen in a different script to create_assets and thus it's printing the timings earlier and then getting overwritten by the extracting/inflating? I can't scroll up far enough in command prompt to get to whatever happens just prior to that part (if that makes sense) so can't confirm this - is the whole log saved anywhere?

Hope that's clear - alternatively, could we write the tictoclog variable that I've got it creating to a .txt file or something like that?

[jeffreyhanson]

Yeah, the reason why its not printing the log out at the end is because after R finishes creating the assets, the Makefile commands then have to copy the files from the build environment to the host computer (which is why the last thing we see is about inflating/extracting files). Could please update the create assets script to save the tictoc log to file (e.g. perhaps using writeLines)? I can then update the Makefile commands to copy across the file to the host computer?

[Louis-Backstrom]

Okay, I believe that should do something along the lines of outputting a .txt file with the required information - it's not pretty but should do the job until one of us can work out something better. @jeffreyhanson can you try to update the makefile commands now?

[jeffreyhanson]

Ok, I've updated the Makefile commands to copy the tictoclog.txt file to the host. I also updated the code when saving the logfile to avoid printing extra row numbers. Can you please give it a go and see if it works?

[Louis-Backstrom]

Okay, trying a rebuild now. ran make rm_image pull_image pull_assets, then deleted the .jpgs in the assets\graphs folder - this should work right?

Will update here or #151 once done with results.

[jeffreyhanson]

Excellent - yeah that should work assuming you pulled the latest version code from GitHub first?

[Louis-Backstrom]

Okay, latest build has a .txt file with timings in it, so I think that's good for now. Closing this issue, although I might reopen it at some stage to neaten things up or some such.

[jeffreyhanson]

Brilliant - thanks