Re: Issue 30952 in chromium-os: VMTest timeout -- logout time regression

[chrom...@googlecode.com]

Updates:
Summary: VMTest timeout -- logout time regression
Owner: nirn...@chromium.org

Comment #4 on issue 30952 by so...@chromium.org: VMTest timeout -- logout
time regression
http://code.google.com/p/chromium-os/issues/detail?id=30952

Looks like we hit a huge logout time regression from the new rev of Chrome
we picked up last night:

Build before Chrome uprev -- vm tests took 14 minutes total
http://chromegw/i/chromiumos/builders/x86%20generic%20full/builds/3405

Build after -- 36 minutes:
http://chromegw/i/chromiumos/builders/x86%20generic%20full/builds/3406

Link to vm test logs:
https://sandbox.google.com/storage/?arg=chromeos-image-archive/x86-generic-full/R21-2301.0.0-a1-b3406#chromeos-image-archive%2Fx86-generic-full%2FR21-2301.0.0-a1-b3406

Here's the status log:
START ---- ---- timestamp=1337170613 localtime=May 16 05:16:53
START login_LoginSuccess login_LoginSuccess timestamp=1337170614
localtime=May 16 05:16:54
GOOD login_LoginSuccess login_LoginSuccess timestamp=1337170760
localtime=May 16 05:19:20 completed successfully
END GOOD login_LoginSuccess login_LoginSuccess timestamp=1337170760
localtime=May 16 05:19:20
START login_CryptohomeUnmounted login_CryptohomeUnmounted
timestamp=1337170761 localtime=May 16 05:19:21
GOOD login_CryptohomeUnmounted login_CryptohomeUnmounted
timestamp=1337170900 localtime=May 16 05:21:40 completed successfully
END GOOD login_CryptohomeUnmounted login_CryptohomeUnmounted
timestamp=1337170900 localtime=May 16 05:21:40
START login_CryptohomeIncognitoUnmounted
login_CryptohomeIncognitoUnmounted timestamp=1337170900 localtime=May 16
05:21:40
GOOD login_CryptohomeIncognitoUnmounted
login_CryptohomeIncognitoUnmounted timestamp=1337171034 localtime=May 16
05:23:54 completed successfully
END GOOD login_CryptohomeIncognitoUnmounted
login_CryptohomeIncognitoUnmounted timestamp=1337171034 localtime=May 16
05:23:54
START login_BadAuthentication login_BadAuthentication timestamp=1337171035
localtime=May 16 05:23:55
GOOD login_BadAuthentication login_BadAuthentication timestamp=1337171167
localtime=May 16 05:26:07 completed successfully
END GOOD login_BadAuthentication login_BadAuthentication
timestamp=1337171167 localtime=May 16 05:26:07
START login_CryptohomeIncognitoMounted login_CryptohomeIncognitoMounted
timestamp=1337171167 localtime=May 16 05:26:07
GOOD login_CryptohomeIncognitoMounted login_CryptohomeIncognitoMounted
timestamp=1337171298 localtime=May 16 05:28:18 completed successfully
END GOOD login_CryptohomeIncognitoMounted login_CryptohomeIncognitoMounted
timestamp=1337171298 localtime=May 16 05:28:18
START security_ProfilePermissions.login security_ProfilePermissions.login
timestamp=1337171299 localtime=May 16 05:28:19
GOOD security_ProfilePermissions.login security_ProfilePermissions.login
timestamp=1337171434 localtime=May 16 05:30:34 completed successfully
END GOOD security_ProfilePermissions.login
security_ProfilePermissions.login timestamp=1337171434 localtime=May 16
05:30:34
START security_ProfilePermissions.BWSI security_ProfilePermissions.BWSI
timestamp=1337171434 localtime=May 16 05:30:34
GOOD security_ProfilePermissions.BWSI security_ProfilePermissions.BWSI
timestamp=1337171566 localtime=May 16 05:32:46 completed successfully
END GOOD security_ProfilePermissions.BWSI security_ProfilePermissions.BWSI
timestamp=1337171566 localtime=May 16 05:32:46
START desktopui_KillRestart.chrome desktopui_KillRestart.chrome
timestamp=1337171566 localtime=May 16 05:32:46
GOOD desktopui_KillRestart.chrome desktopui_KillRestart.chrome
timestamp=1337171567 localtime=May 16 05:32:47 completed successfully
END GOOD desktopui_KillRestart.chrome desktopui_KillRestart.chrome
timestamp=1337171567 localtime=May 16 05:32:47
START desktopui_KillRestart.session desktopui_KillRestart.session
timestamp=1337171568 localtime=May 16 05:32:48
GOOD desktopui_KillRestart.session desktopui_KillRestart.session
timestamp=1337171570 localtime=May 16 05:32:50 completed successfully
END GOOD desktopui_KillRestart.session desktopui_KillRestart.session
timestamp=1337171570 localtime=May 16 05:32:50
START logging_CrashSender logging_CrashSender timestamp=1337171571
localtime=May 16 05:32:51
GOOD logging_CrashSender logging_CrashSender timestamp=1337171582
localtime=May 16 05:33:02 completed successfully
END GOOD logging_CrashSender logging_CrashSender timestamp=1337171582
localtime=May 16 05:33:02
START login_OwnershipApi login_OwnershipApi timestamp=1337171583
localtime=May 16 05:33:03
GOOD login_OwnershipApi login_OwnershipApi timestamp=1337171841
localtime=May 16 05:37:21 completed successfully
END GOOD login_OwnershipApi login_OwnershipApi timestamp=1337171841
localtime=May 16 05:37:21
START platform_OSLimits platform_OSLimits timestamp=1337171842
localtime=May 16 05:37:22
GOOD platform_OSLimits platform_OSLimits timestamp=1337171843
localtime=May 16 05:37:23 completed successfully
END GOOD platform_OSLimits platform_OSLimits timestamp=1337171843
localtime=May 16 05:37:23
START login_CryptohomeMounted login_CryptohomeMounted timestamp=1337171843
localtime=May 16 05:37:23
GOOD login_CryptohomeMounted login_CryptohomeMounted timestamp=1337171986
localtime=May 16 05:39:46 completed successfully
END GOOD login_CryptohomeMounted login_CryptohomeMounted
timestamp=1337171986 localtime=May 16 05:39:46
START desktopui_ScreenLocker desktopui_ScreenLocker timestamp=1337171986
localtime=May 16 05:39:46
GOOD desktopui_ScreenLocker desktopui_ScreenLocker timestamp=1337172122
localtime=May 16 05:42:02 completed successfully
END GOOD desktopui_ScreenLocker desktopui_ScreenLocker
timestamp=1337172122 localtime=May 16 05:42:02
START logging_UserCrash logging_UserCrash timestamp=1337172123
localtime=May 16 05:42:03
GOOD logging_UserCrash logging_UserCrash timestamp=1337172138
localtime=May 16 05:42:18 completed successfully
END GOOD logging_UserCrash logging_UserCrash timestamp=1337172138
localtime=May 16 05:42:18
START platform_FilePerms platform_FilePerms timestamp=1337172138
localtime=May 16 05:42:18
GOOD platform_FilePerms platform_FilePerms timestamp=1337172139
localtime=May 16 05:42:19 completed successfully
END GOOD platform_FilePerms platform_FilePerms timestamp=1337172139
localtime=May 16 05:42:19
END GOOD ---- ---- timestamp=1337172140 localtime=May 16 05:42:20

We basically jumped 20 second login/logout time to 2 minutes.

Sheriffs are pinning Chrome back until this is resolved. Nirnimesh, it
seems like you made logout changes. Can you take a look?

Here's the list of changes in the Chrome uprev:
http://build.chromium.org/f/chromium/perf/dashboard/ui/changelog.html?url=/trunk/src&range=137076:137350&mode=html

[chrom...@googlecode.com]

Comment #5 on issue 30952 by so...@chromium.org: VMTest timeout -- logout
time regression
http://code.google.com/p/chromium-os/issues/detail?id=30952

Also taking a look at the chromium.chromiumos waterfall, it looks like we
jumped from 5 minute vm testing to 27 minutes starting with build:
http://chromegw/i/chromium.chromiumos/builders/ChromiumOS%20%28x86%29/builds/5130

The blamelist there should be accurate