Add Traces to BootAnimation.cpp

This is to better understand boot regression. There have been instances
of logcat not containing boot complete messages.

Test: Manual. Checked boot trace if the traces contain Boot Animation
slices
Bug: 271576143

Change-Id: I8a3277ca02e22612389def79bfb0e3a3608e2731
diff --git a/cmds/bootanimation/BootAnimation.cpp b/cmds/bootanimation/BootAnimation.cpp
index a8b6c0b..c216d16 100644
--- a/cmds/bootanimation/BootAnimation.cpp
+++ b/cmds/bootanimation/BootAnimation.cpp
@@ -16,6 +16,7 @@
 
 #define LOG_NDEBUG 0
 #define LOG_TAG "BootAnimation"
+#define ATRACE_TAG ATRACE_TAG_GRAPHICS
 
 #include <vector>
 
@@ -28,6 +29,7 @@
 #include <math.h>
 #include <fcntl.h>
 #include <utils/misc.h>
+#include <utils/Trace.h>
 #include <signal.h>
 #include <time.h>
 
@@ -200,6 +202,7 @@
 BootAnimation::BootAnimation(sp<Callbacks> callbacks)
         : Thread(false), mLooper(new Looper(false)), mClockEnabled(true), mTimeIsAccurate(false),
         mTimeFormat12Hour(false), mTimeCheckThread(nullptr), mCallbacks(callbacks) {
+    ATRACE_CALL();
     mSession = new SurfaceComposerClient();
 
     std::string powerCtl = android::base::GetProperty("sys.powerctl", "");
@@ -213,6 +216,7 @@
 }
 
 BootAnimation::~BootAnimation() {
+    ATRACE_CALL();
     if (mAnimation != nullptr) {
         releaseAnimation(mAnimation);
         mAnimation = nullptr;
@@ -222,6 +226,7 @@
 }
 
 void BootAnimation::onFirstRef() {
+    ATRACE_CALL();
     status_t err = mSession->linkToComposerDeath(this);
     SLOGE_IF(err, "linkToComposerDeath failed (%s) ", strerror(-err));
     if (err == NO_ERROR) {
@@ -240,6 +245,7 @@
 }
 
 void BootAnimation::binderDied(const wp<IBinder>&) {
+    ATRACE_CALL();
     // woah, surfaceflinger died!
     SLOGD("SurfaceFlinger died, exiting...");
 
@@ -251,6 +257,7 @@
 
 static void* decodeImage(const void* encodedData, size_t dataLength, AndroidBitmapInfo* outInfo,
     bool premultiplyAlpha) {
+    ATRACE_CALL();
     AImageDecoder* decoder = nullptr;
     AImageDecoder_createFromBuffer(encodedData, dataLength, &decoder);
     if (!decoder) {
@@ -282,6 +289,7 @@
 
 status_t BootAnimation::initTexture(Texture* texture, AssetManager& assets,
         const char* name, bool premultiplyAlpha) {
+    ATRACE_CALL();
     Asset* asset = assets.open(name, Asset::ACCESS_BUFFER);
     if (asset == nullptr)
         return NO_INIT;
@@ -338,6 +346,7 @@
 
 status_t BootAnimation::initTexture(FileMap* map, int* width, int* height,
     bool premultiplyAlpha) {
+    ATRACE_CALL();
     AndroidBitmapInfo bitmapInfo;
     void* pixels = decodeImage(map->getDataPtr(), map->getDataLength(), &bitmapInfo,
         premultiplyAlpha);
@@ -404,10 +413,12 @@
 
 public:
     DisplayEventCallback(BootAnimation* bootAnimation) {
+        ATRACE_CALL();
         mBootAnimation = bootAnimation;
     }
 
     int handleEvent(int /* fd */, int events, void* /* data */) {
+        ATRACE_CALL();
         if (events & (Looper::EVENT_ERROR | Looper::EVENT_HANGUP)) {
             ALOGE("Display event receiver pipe was closed or an error occurred. events=0x%x",
                     events);
@@ -492,6 +503,7 @@
 }
 
 status_t BootAnimation::readyToRun() {
+    ATRACE_CALL();
     mAssets.addDefaultAssets();
 
     const std::vector<PhysicalDisplayId> ids = SurfaceComposerClient::getPhysicalDisplayIds();
@@ -628,6 +640,7 @@
 }
 
 void BootAnimation::rotateAwayFromNaturalOrientationIfNeeded() {
+    ATRACE_CALL();
     const auto orientation = parseOrientationProperty();
 
     if (orientation == ui::ROTATION_0) {
@@ -650,6 +663,7 @@
 }
 
 ui::Rotation BootAnimation::parseOrientationProperty() {
+    ATRACE_CALL();
     const auto displayIds = SurfaceComposerClient::getPhysicalDisplayIds();
     if (displayIds.size() == 0) {
         return ui::ROTATION_0;
@@ -672,11 +686,13 @@
 }
 
 void BootAnimation::projectSceneToWindow() {
+    ATRACE_CALL();
     glViewport(0, 0, mWidth, mHeight);
     glScissor(0, 0, mWidth, mHeight);
 }
 
 void BootAnimation::resizeSurface(int newWidth, int newHeight) {
+    ATRACE_CALL();
     // We assume this function is called on the animation thread.
     if (newWidth == mWidth && newHeight == mHeight) {
         return;
@@ -704,6 +720,7 @@
 }
 
 bool BootAnimation::preloadAnimation() {
+    ATRACE_CALL();
     findBootAnimationFile();
     if (!mZipFileName.isEmpty()) {
         mAnimation = loadAnimation(mZipFileName);
@@ -714,6 +731,7 @@
 }
 
 bool BootAnimation::findBootAnimationFileInternal(const std::vector<std::string> &files) {
+    ATRACE_CALL();
     for (const std::string& f : files) {
         if (access(f.c_str(), R_OK) == 0) {
             mZipFileName = f.c_str();
@@ -724,6 +742,7 @@
 }
 
 void BootAnimation::findBootAnimationFile() {
+    ATRACE_CALL();
     const bool playDarkAnim = android::base::GetIntProperty("ro.boot.theme", 0) == 1;
     static const std::vector<std::string> bootFiles = {
         APEX_BOOTANIMATION_FILE, playDarkAnim ? PRODUCT_BOOTANIMATION_DARK_FILE : PRODUCT_BOOTANIMATION_FILE,
@@ -747,6 +766,7 @@
 }
 
 GLuint compileShader(GLenum shaderType, const GLchar *source) {
+    ATRACE_CALL();
     GLuint shader = glCreateShader(shaderType);
     glShaderSource(shader, 1, &source, 0);
     glCompileShader(shader);
@@ -765,6 +785,7 @@
 }
 
 GLuint linkShader(GLuint vertexShader, GLuint fragmentShader) {
+    ATRACE_CALL();
     GLuint program = glCreateProgram();
     glAttachShader(program, vertexShader);
     glAttachShader(program, fragmentShader);
@@ -780,6 +801,7 @@
 }
 
 void BootAnimation::initShaders() {
+    ATRACE_CALL();
     bool dynamicColoringEnabled = mAnimation != nullptr && mAnimation->dynamicColoringEnabled;
     GLuint vertexShader = compileShader(GL_VERTEX_SHADER, (const GLchar *)VERTEX_SHADER_SOURCE);
     GLuint imageFragmentShader =
@@ -813,6 +835,7 @@
 }
 
 bool BootAnimation::threadLoop() {
+    ATRACE_CALL();
     bool result;
     initShaders();
 
@@ -838,6 +861,7 @@
 }
 
 bool BootAnimation::android() {
+    ATRACE_CALL();
     glActiveTexture(GL_TEXTURE0);
 
     SLOGD("%sAnimationShownTiming start time: %" PRId64 "ms", mShuttingDown ? "Shutdown" : "Boot",
@@ -905,6 +929,7 @@
 }
 
 void BootAnimation::checkExit() {
+    ATRACE_CALL();
     // Allow surface flinger to gracefully request shutdown
     char value[PROPERTY_VALUE_MAX];
     property_get(EXIT_PROP_NAME, value, "0");
@@ -915,10 +940,12 @@
 }
 
 bool BootAnimation::validClock(const Animation::Part& part) {
+    ATRACE_CALL();
     return part.clockPosX != TEXT_MISSING_VALUE && part.clockPosY != TEXT_MISSING_VALUE;
 }
 
 bool parseTextCoord(const char* str, int* dest) {
+    ATRACE_CALL();
     if (strcmp("c", str) == 0) {
         *dest = TEXT_CENTER_VALUE;
         return true;
@@ -935,6 +962,7 @@
 
 // Parse two position coordinates. If only string is non-empty, treat it as the y value.
 void parsePosition(const char* str1, const char* str2, int* x, int* y) {
+    ATRACE_CALL();
     bool success = false;
     if (strlen(str1) == 0) {  // No values were specified
         // success = false
@@ -963,6 +991,7 @@
 // If the input string isn't valid, parseColor returns false and color is
 // left unchanged.
 static bool parseColor(const char str[7], float color[3]) {
+    ATRACE_CALL();
     float tmpColor[3];
     for (int i = 0; i < 3; i++) {
         int val = 0;
@@ -985,6 +1014,7 @@
 // If the input color string is empty, set color with values in defaultColor.
 static void parseColorDecimalString(const std::string& colorString,
     float color[3], float defaultColor[3]) {
+    ATRACE_CALL();
     if (colorString == "") {
         memcpy(color, defaultColor, sizeof(float) * 3);
         return;
@@ -996,6 +1026,7 @@
 }
 
 static bool readFile(ZipFileRO* zip, const char* name, String8& outString) {
+    ATRACE_CALL();
     ZipEntryRO entry = zip->findEntryByName(name);
     SLOGE_IF(!entry, "couldn't find %s", name);
     if (!entry) {
@@ -1018,6 +1049,7 @@
 // columns are the printable ASCII characters 0x20 - 0x7f.  The
 // top row is regular text; the bottom row is bold.
 status_t BootAnimation::initFont(Font* font, const char* fallback) {
+    ATRACE_CALL();
     status_t status = NO_ERROR;
 
     if (font->map != nullptr) {
@@ -1045,6 +1077,7 @@
 }
 
 void BootAnimation::drawText(const char* str, const Font& font, bool bold, int* x, int* y) {
+    ATRACE_CALL();
     glEnable(GL_BLEND);  // Allow us to draw on top of the animation
     glBindTexture(GL_TEXTURE_2D, font.texture.name);
     glUseProgram(mTextShader);
@@ -1092,6 +1125,7 @@
 
 // We render 12 or 24 hour time.
 void BootAnimation::drawClock(const Font& font, const int xPos, const int yPos) {
+    ATRACE_CALL();
     static constexpr char TIME_FORMAT_12[] = "%l:%M";
     static constexpr char TIME_FORMAT_24[] = "%H:%M";
     static constexpr int TIME_LENGTH = 6;
@@ -1117,6 +1151,7 @@
 }
 
 void BootAnimation::drawProgress(int percent, const Font& font, const int xPos, const int yPos) {
+    ATRACE_CALL();
     static constexpr int PERCENT_LENGTH = 5;
 
     char percentBuff[PERCENT_LENGTH];
@@ -1129,6 +1164,7 @@
 }
 
 bool BootAnimation::parseAnimationDesc(Animation& animation)  {
+    ATRACE_CALL();
     String8 desString;
 
     if (!readFile(animation.zip, "desc.txt", desString)) {
@@ -1252,6 +1288,7 @@
 }
 
 bool BootAnimation::preloadZip(Animation& animation) {
+    ATRACE_CALL();
     // read all the data structures
     const size_t pcount = animation.parts.size();
     void *cookie = nullptr;
@@ -1357,6 +1394,7 @@
 }
 
 bool BootAnimation::movie() {
+    ATRACE_CALL();
     if (mAnimation == nullptr) {
         mAnimation = loadAnimation(mZipFileName);
     }
@@ -1450,6 +1488,7 @@
 bool BootAnimation::shouldStopPlayingPart(const Animation::Part& part,
                                           const int fadedFramesCount,
                                           const int lastDisplayedProgress) {
+    ATRACE_CALL();
     // stop playing only if it is time to exit and it's a partial part which has been faded out
     return exitPending() && !part.playUntilComplete && fadedFramesCount >= part.framesToFadeCount &&
         (lastDisplayedProgress == 0 || lastDisplayedProgress == 100);
@@ -1461,6 +1500,7 @@
 }
 
 void BootAnimation::drawTexturedQuad(float xStart, float yStart, float width, float height) {
+    ATRACE_CALL();
     // Map coordinates from screen space to world space.
     float x0 = mapLinear(xStart, 0, mWidth, -1, 1);
     float y0 = mapLinear(yStart, 0, mHeight, -1, 1);
@@ -1484,6 +1524,7 @@
 }
 
 void BootAnimation::initDynamicColors() {
+    ATRACE_CALL();
     for (int i = 0; i < DYNAMIC_COLOR_COUNT; i++) {
         const auto syspropName = "persist.bootanim.color" + std::to_string(i + 1);
         const auto syspropValue = android::base::GetProperty(syspropName, "");
@@ -1510,6 +1551,7 @@
 }
 
 bool BootAnimation::playAnimation(const Animation& animation) {
+    ATRACE_CALL();
     const size_t pcount = animation.parts.size();
     nsecs_t frameDuration = s2ns(1) / animation.fps;
 
@@ -1720,12 +1762,14 @@
 }
 
 void BootAnimation::processDisplayEvents() {
+    ATRACE_CALL();
     // This will poll mDisplayEventReceiver and if there are new events it'll call
     // displayEventCallback synchronously.
     mLooper->pollOnce(0);
 }
 
 void BootAnimation::handleViewport(nsecs_t timestep) {
+    ATRACE_CALL();
     if (mShuttingDown || !mFlingerSurfaceControl || mTargetInset == 0) {
         return;
     }
@@ -1768,6 +1812,7 @@
 }
 
 void BootAnimation::releaseAnimation(Animation* animation) const {
+    ATRACE_CALL();
     for (Vector<Animation::Part>::iterator it = animation->parts.begin(),
          e = animation->parts.end(); it != e; ++it) {
         if (it->animation)
@@ -1779,6 +1824,7 @@
 }
 
 BootAnimation::Animation* BootAnimation::loadAnimation(const String8& fn) {
+    ATRACE_CALL();
     if (mLoadedFiles.indexOf(fn) >= 0) {
         SLOGE("File \"%s\" is already loaded. Cyclic ref is not allowed",
             fn.string());
@@ -1810,6 +1856,7 @@
 }
 
 bool BootAnimation::updateIsTimeAccurate() {
+    ATRACE_CALL();
     static constexpr long long MAX_TIME_IN_PAST =   60000LL * 60LL * 24LL * 30LL;  // 30 days
     static constexpr long long MAX_TIME_IN_FUTURE = 60000LL * 90LL;  // 90 minutes
 
@@ -1853,11 +1900,13 @@
     mInotifyFd(-1), mBootAnimWd(-1), mTimeWd(-1), mBootAnimation(bootAnimation) {}
 
 BootAnimation::TimeCheckThread::~TimeCheckThread() {
+    ATRACE_CALL();
     // mInotifyFd may be -1 but that's ok since we're not at risk of attempting to close a valid FD.
     close(mInotifyFd);
 }
 
 bool BootAnimation::TimeCheckThread::threadLoop() {
+    ATRACE_CALL();
     bool shouldLoop = doThreadLoop() && !mBootAnimation->mTimeIsAccurate
         && mBootAnimation->mClockEnabled;
     if (!shouldLoop) {
@@ -1868,6 +1917,7 @@
 }
 
 bool BootAnimation::TimeCheckThread::doThreadLoop() {
+    ATRACE_CALL();
     static constexpr int BUFF_LEN (10 * (sizeof(struct inotify_event) + NAME_MAX + 1));
 
     // Poll instead of doing a blocking read so the Thread can exit if requested.
@@ -1905,6 +1955,7 @@
 }
 
 void BootAnimation::TimeCheckThread::addTimeDirWatch() {
+        ATRACE_CALL();
         mTimeWd = inotify_add_watch(mInotifyFd, BOOTANIM_TIME_DIR_PATH,
                 IN_CLOSE_WRITE | IN_MOVED_TO | IN_ATTRIB);
         if (mTimeWd > 0) {
@@ -1915,6 +1966,7 @@
 }
 
 status_t BootAnimation::TimeCheckThread::readyToRun() {
+    ATRACE_CALL();
     mInotifyFd = inotify_init();
     if (mInotifyFd < 0) {
         SLOGE("Could not initialize inotify fd");