New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 798537 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
User never visited
Closed: Jan 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

"wakeup source activated" logspam in /var/log/messages

Project Member Reported by cernekee@chromium.org, Jan 2 2018

Issue description

May be related to  bug 784000 , but this is a slightly different message.

10272.0.0 (Official Build) canary-channel bob
65.0.3299.0 (Official Build) canary (32-bit)
This bob is a corp-enrolled DVT2

2018-01-02T20:32:03.143161+00:00 INFO kernel: [  109.641577] spi5.0: wakeup source activated, active_count=75
2018-01-02T20:32:03.215155+00:00 INFO kernel: [  109.713751] spi5.0: wakeup source activated, active_count=76
2018-01-02T20:32:03.273054+00:00 INFO kernel: [  109.771834] spi5.0: wakeup source activated, active_count=77
2018-01-02T20:32:03.337202+00:00 INFO kernel: [  109.836370] spi5.0: wakeup source activated, active_count=78
2018-01-02T20:32:03.408194+00:00 INFO kernel: [  109.907002] spi5.0: wakeup source activated, active_count=79
2018-01-02T20:32:03.432243+00:00 INFO kernel: [  109.931455] spi5.0: wakeup source activated, active_count=80
2018-01-02T20:32:03.456208+00:00 INFO kernel: [  109.954567] spi5.0: wakeup source activated, active_count=81
2018-01-02T20:32:03.504155+00:00 INFO kernel: [  110.003421] spi5.0: wakeup source activated, active_count=82
2018-01-02T20:32:03.507229+00:00 INFO kernel: [  110.005674] spi5.0: wakeup source activated, active_count=83
2018-01-02T20:32:03.561549+00:00 INFO kernel: [  110.060565] spi5.0: wakeup source activated, active_count=84
2018-01-02T20:32:03.607721+00:00 INFO kernel: [  110.106914] spi5.0: wakeup source activated, active_count=85
2018-01-02T20:32:03.685211+00:00 INFO kernel: [  110.183984] spi5.0: wakeup source activated, active_count=86
2018-01-02T20:32:03.698208+00:00 INFO kernel: [  110.197228] spi5.0: wakeup source activated, active_count=87
2018-01-02T20:32:03.741174+00:00 INFO kernel: [  110.240163] spi5.0: wakeup source activated, active_count=88
2018-01-02T20:32:03.800175+00:00 INFO kernel: [  110.299010] spi5.0: wakeup source activated, active_count=89
2018-01-02T20:32:03.894161+00:00 INFO kernel: [  110.392613] spi5.0: wakeup source activated, active_count=90
2018-01-02T20:32:04.222182+00:00 INFO kernel: [  110.720919] spi5.0: wakeup source activated, active_count=91
2018-01-02T20:32:04.282280+00:00 INFO kernel: [  110.781451] spi5.0: wakeup source activated, active_count=92
2018-01-02T20:32:04.427227+00:00 INFO kernel: [  110.926138] spi5.0: wakeup source activated, active_count=93
2018-01-02T20:32:04.453200+00:00 INFO kernel: [  110.951600] spi5.0: wakeup source activated, active_count=94
2018-01-02T20:32:04.729152+00:00 INFO kernel: [  111.228145] spi5.0: wakeup source activated, active_count=95
2018-01-02T20:32:04.863802+00:00 INFO kernel: [  111.363103] spi5.0: wakeup source activated, active_count=96
2018-01-02T20:32:04.883164+00:00 INFO kernel: [  111.382040] spi5.0: wakeup source activated, active_count=97
2018-01-02T20:32:04.932174+00:00 INFO kernel: [  111.431019] spi5.0: wakeup source activated, active_count=98
2018-01-02T20:32:04.998941+00:00 INFO kernel: [  111.497877] spi5.0: wakeup source activated, active_count=99
2018-01-02T20:32:05.052245+00:00 INFO kernel: [  111.550618] spi5.0: wakeup source activated, active_count=100
2018-01-02T20:32:05.089233+00:00 INFO kernel: [  111.587637] spi5.0: wakeup source activated, active_count=101
2018-01-02T20:32:05.145189+00:00 INFO kernel: [  111.644048] spi5.0: wakeup source activated, active_count=102
2018-01-02T20:32:05.180208+00:00 INFO kernel: [  111.679182] spi5.0: wakeup source activated, active_count=103
2018-01-02T20:32:05.237214+00:00 INFO kernel: [  111.736040] spi5.0: wakeup source activated, active_count=104
2018-01-02T20:32:05.255160+00:00 INFO kernel: [  111.754271] spi5.0: wakeup source activated, active_count=105
2018-01-02T20:32:05.352249+00:00 INFO kernel: [  111.851452] spi5.0: wakeup source activated, active_count=106
2018-01-02T20:32:05.367222+00:00 INFO kernel: [  111.866039] spi5.0: wakeup source activated, active_count=107
2018-01-02T20:32:05.461194+00:00 INFO kernel: [  111.960175] spi5.0: wakeup source activated, active_count=108
2018-01-02T20:32:05.483166+00:00 INFO kernel: [  111.981711] spi5.0: wakeup source activated, active_count=109
2018-01-02T20:32:05.571185+00:00 INFO kernel: [  112.070371] spi5.0: wakeup source activated, active_count=110
2018-01-02T20:32:05.608145+00:00 INFO kernel: [  112.107437] spi5.0: wakeup source activated, active_count=111
2018-01-02T20:32:05.629120+00:00 INFO kernel: [  112.127904] spi5.0: wakeup source activated, active_count=112
2018-01-02T20:32:05.704211+00:00 INFO kernel: [  112.203408] spi5.0: wakeup source activated, active_count=113
2018-01-02T20:32:05.729214+00:00 INFO kernel: [  112.228169] spi5.0: wakeup source activated, active_count=114
2018-01-02T20:32:05.922244+00:00 INFO kernel: [  112.421252] spi5.0: wakeup source activated, active_count=115
2018-01-02T20:32:06.061147+00:00 INFO kernel: [  112.560443] spi5.0: wakeup source activated, active_count=116
2018-01-02T20:32:07.955802+00:00 INFO kernel: [  114.454665] spi5.0: wakeup source activated, active_count=117
2018-01-02T20:32:08.046196+00:00 INFO kernel: [  114.545169] spi5.0: wakeup source activated, active_count=118
2018-01-02T20:32:08.067191+00:00 INFO kernel: [  114.566384] spi5.0: wakeup source activated, active_count=119
2018-01-02T20:32:08.150202+00:00 INFO kernel: [  114.648555] spi5.0: wakeup source activated, active_count=120
2018-01-02T20:32:08.212212+00:00 INFO kernel: [  114.710674] spi5.0: wakeup source activated, active_count=121
2018-01-02T20:32:08.295045+00:00 INFO kernel: [  114.793663] spi5.0: wakeup source activated, active_count=122
2018-01-02T20:32:08.307189+00:00 INFO kernel: [  114.805692] spi5.0: wakeup source activated, active_count=123
2018-01-02T20:32:08.379174+00:00 INFO kernel: [  114.877978] spi5.0: wakeup source activated, active_count=124
2018-01-02T20:32:08.559236+00:00 INFO kernel: [  115.058336] spi5.0: wakeup source activated, active_count=125
2018-01-02T20:32:08.897234+00:00 INFO kernel: [  115.396112] spi5.0: wakeup source activated, active_count=126
2018-01-02T20:32:09.110170+00:00 INFO kernel: [  115.608864] spi5.0: wakeup source activated, active_count=127
2018-01-02T20:32:09.235178+00:00 INFO kernel: [  115.733911] spi5.0: wakeup source activated, active_count=128
2018-01-02T20:32:10.067258+00:00 INFO kernel: [  116.566471] spi5.0: wakeup source activated, active_count=129
2018-01-02T20:32:10.181174+00:00 INFO kernel: [  116.679555] spi5.0: wakeup source activated, active_count=130
2018-01-02T20:32:10.327177+00:00 INFO kernel: [  116.825980] spi5.0: wakeup source activated, active_count=131
2018-01-02T20:32:10.620188+00:00 INFO kernel: [  117.119044] spi5.0: wakeup source activated, active_count=132
2018-01-02T20:32:10.720156+00:00 INFO kernel: [  117.218543] spi5.0: wakeup source activated, active_count=133
2018-01-02T20:32:10.742188+00:00 INFO kernel: [  117.240925] spi5.0: wakeup source activated, active_count=134
2018-01-02T20:32:11.348175+00:00 INFO kernel: [  117.847295] spi5.0: wakeup source activated, active_count=135
2018-01-02T20:32:11.448190+00:00 INFO kernel: [  117.946879] spi5.0: wakeup source activated, active_count=136
2018-01-02T20:32:11.524172+00:00 INFO kernel: [  118.023205] spi5.0: wakeup source activated, active_count=137
2018-01-02T20:32:11.591184+00:00 INFO kernel: [  118.089621] spi5.0: wakeup source activated, active_count=138
2018-01-02T20:32:12.332659+00:00 INFO kernel: [  118.831549] spi5.0: wakeup source activated, active_count=139
2018-01-02T20:32:12.435192+00:00 INFO kernel: [  118.933694] spi5.0: wakeup source activated, active_count=140
2018-01-02T20:32:12.867274+00:00 INFO kernel: [  119.366482] spi5.0: wakeup source activated, active_count=141
2018-01-02T20:32:12.959321+00:00 INFO kernel: [  119.458490] spi5.0: wakeup source activated, active_count=142
2018-01-02T20:32:12.971185+00:00 INFO kernel: [  119.470155] spi5.0: wakeup source activated, active_count=143
2018-01-02T20:32:13.049151+00:00 INFO kernel: [  119.547927] spi5.0: wakeup source activated, active_count=144
2018-01-02T20:32:13.205170+00:00 INFO kernel: [  119.703676] spi5.0: wakeup source activated, active_count=145
2018-01-02T20:32:13.273171+00:00 INFO kernel: [  119.772122] spi5.0: wakeup source activated, active_count=146
2018-01-02T20:32:13.372257+00:00 INFO kernel: [  119.871391] spi5.0: wakeup source activated, active_count=147
2018-01-02T20:32:13.423200+00:00 INFO kernel: [  119.921891] spi5.0: wakeup source activated, active_count=148
2018-01-02T20:32:13.509155+00:00 INFO kernel: [  120.007530] spi5.0: wakeup source activated, active_count=149
2018-01-02T20:32:13.583186+00:00 INFO kernel: [  120.082064] spi5.0: wakeup source activated, active_count=150
2018-01-02T20:32:13.651194+00:00 INFO kernel: [  120.149625] spi5.0: wakeup source activated, active_count=151
2018-01-02T20:32:13.716179+00:00 INFO kernel: [  120.214752] spi5.0: wakeup source activated, active_count=152
2018-01-02T20:32:13.779165+00:00 INFO kernel: [  120.277905] spi5.0: wakeup source activated, active_count=153
2018-01-02T20:32:13.867185+00:00 INFO kernel: [  120.365780] spi5.0: wakeup source activated, active_count=154
2018-01-02T20:32:14.371192+00:00 INFO kernel: [  120.869674] spi5.0: wakeup source activated, active_count=155
2018-01-02T20:32:14.517219+00:00 INFO kernel: [  121.016383] spi5.0: wakeup source activated, active_count=156

2018-01-02T20:33:03.447153+00:00 INFO kernel: [  169.945655] spi5.0: wakeup source activated, active_count=169
2018-01-02T20:33:03.527154+00:00 INFO kernel: [  170.025613] spi5.0: wakeup source activated, active_count=170
2018-01-02T20:33:03.581169+00:00 INFO kernel: [  170.079667] spi5.0: wakeup source activated, active_count=171
2018-01-02T20:33:03.680166+00:00 INFO kernel: [  170.179234] spi5.0: wakeup source activated, active_count=172
2018-01-02T20:33:03.697160+00:00 INFO kernel: [  170.196311] spi5.0: wakeup source activated, active_count=173
2018-01-02T20:33:03.782982+00:00 INFO kernel: [  170.282175] spi5.0: wakeup source activated, active_count=174
2018-01-02T20:33:03.812164+00:00 INFO kernel: [  170.311014] spi5.0: wakeup source activated, active_count=175
2018-01-02T20:33:03.901168+00:00 INFO kernel: [  170.400098] spi5.0: wakeup source activated, active_count=176
2018-01-02T20:33:03.910193+00:00 INFO kernel: [  170.409468] spi5.0: wakeup source activated, active_count=177
2018-01-02T20:33:03.931180+00:00 INFO kernel: [  170.430419] spi5.0: wakeup source activated, active_count=178
2018-01-02T20:33:03.953385+00:00 INFO kernel: [  170.448179] spi5.0: wakeup source activated, active_count=179
2018-01-02T20:33:04.039161+00:00 INFO kernel: [  170.537746] spi5.0: wakeup source activated, active_count=180
2018-01-02T20:33:04.046177+00:00 INFO kernel: [  170.544591] spi5.0: wakeup source activated, active_count=181
2018-01-02T20:33:04.132160+00:00 INFO kernel: [  170.631400] spi5.0: wakeup source activated, active_count=182
2018-01-02T20:33:04.169205+00:00 INFO kernel: [  170.668101] spi5.0: wakeup source activated, active_count=183
2018-01-02T20:33:04.256180+00:00 INFO kernel: [  170.754660] spi5.0: wakeup source activated, active_count=184
2018-01-02T20:33:04.310161+00:00 INFO kernel: [  170.809155] spi5.0: wakeup source activated, active_count=185
2018-01-02T20:33:04.322160+00:00 INFO kernel: [  170.820987] spi5.0: wakeup source activated, active_count=186
2018-01-02T20:33:04.376178+00:00 INFO kernel: [  170.875233] binder: 4545:4552 refcount change on invalid ref 8
2018-01-02T20:33:04.396021+00:00 INFO kernel: [  170.894359] spi5.0: wakeup source activated, active_count=187
2018-01-02T20:33:04.414166+00:00 INFO kernel: [  170.912651] spi5.0: wakeup source activated, active_count=188
2018-01-02T20:33:04.586169+00:00 INFO kernel: [  171.085270] spi5.0: wakeup source activated, active_count=189
2018-01-02T20:33:04.701156+00:00 INFO kernel: [  171.199934] spi5.0: wakeup source activated, active_count=190
2018-01-02T20:33:05.120209+00:00 INFO kernel: [  171.618879] spi5.0: wakeup source activated, active_count=191
2018-01-02T20:33:05.190169+00:00 INFO kernel: [  171.688796] spi5.0: wakeup source activated, active_count=192
2018-01-02T20:33:05.256151+00:00 INFO kernel: [  171.755180] spi5.0: wakeup source activated, active_count=193
2018-01-02T20:33:05.342156+00:00 INFO kernel: [  171.840955] spi5.0: wakeup source activated, active_count=194
2018-01-02T20:33:05.350224+00:00 INFO kernel: [  171.849112] spi5.0: wakeup source activated, active_count=195
2018-01-02T20:33:05.449285+00:00 INFO kernel: [  171.948162] spi5.0: wakeup source activated, active_count=196
2018-01-02T20:33:05.467201+00:00 INFO kernel: [  171.964337] spi5.0: wakeup source activated, active_count=197
2018-01-02T20:33:05.561173+00:00 INFO kernel: [  172.060129] spi5.0: wakeup source activated, active_count=198

2018-01-02T20:35:40.321273+00:00 INFO kernel: [  326.819672] spi5.0: wakeup source activated, active_count=297
2018-01-02T20:35:40.420271+00:00 INFO kernel: [  326.919327] spi5.0: wakeup source activated, active_count=298
2018-01-02T20:35:40.503082+00:00 INFO kernel: [  327.002324] spi5.0: wakeup source activated, active_count=299
2018-01-02T20:35:40.523467+00:00 INFO kernel: [  327.022389] spi5.0: wakeup source activated, active_count=300
2018-01-02T20:35:40.887182+00:00 INFO kernel: [  327.385941] spi5.0: wakeup source activated, active_count=301
2018-01-02T20:35:40.982159+00:00 INFO kernel: [  327.481090] spi5.0: wakeup source activated, active_count=302
2018-01-02T20:35:40.994218+00:00 INFO kernel: [  327.493472] spi5.0: wakeup source activated, active_count=303
2018-01-02T20:35:41.029410+00:00 INFO kernel: [  327.528667] spi5.0: wakeup source activated, active_count=304
2018-01-02T20:35:41.087176+00:00 INFO kernel: [  327.585540] spi5.0: wakeup source activated, active_count=305
2018-01-02T20:35:41.102159+00:00 INFO kernel: [  327.601313] spi5.0: wakeup source activated, active_count=306
2018-01-02T20:35:41.139184+00:00 INFO kernel: [  327.638499] spi5.0: wakeup source activated, active_count=307
2018-01-02T20:35:41.218168+00:00 INFO kernel: [  327.717475] spi5.0: wakeup source activated, active_count=308
2018-01-02T20:35:41.304193+00:00 INFO kernel: [  327.802637] spi5.0: wakeup source activated, active_count=309
2018-01-02T20:35:41.351166+00:00 INFO kernel: [  327.850254] spi5.0: wakeup source activated, active_count=310
2018-01-02T20:35:41.449186+00:00 INFO kernel: [  327.947569] spi5.0: wakeup source activated, active_count=311
2018-01-02T20:35:41.491152+00:00 INFO kernel: [  327.990442] spi5.0: wakeup source activated, active_count=312
2018-01-02T20:35:41.583201+00:00 INFO kernel: [  328.082247] spi5.0: wakeup source activated, active_count=313
2018-01-02T20:35:41.673873+00:00 INFO kernel: [  328.173060] spi5.0: wakeup source activated, active_count=314
2018-01-02T20:35:41.723222+00:00 INFO kernel: [  328.222441] spi5.0: wakeup source activated, active_count=315
2018-01-02T20:35:41.801188+00:00 INFO kernel: [  328.300444] spi5.0: wakeup source activated, active_count=316
2018-01-02T20:35:41.862158+00:00 INFO kernel: [  328.360706] spi5.0: wakeup source activated, active_count=317
2018-01-02T20:35:41.928165+00:00 INFO kernel: [  328.426775] spi5.0: wakeup source activated, active_count=318
2018-01-02T20:35:41.948360+00:00 INFO kernel: [  328.447627] spi5.0: wakeup source activated, active_count=319
2018-01-02T20:35:41.986157+00:00 INFO kernel: [  328.485306] spi5.0: wakeup source activated, active_count=320
2018-01-02T20:35:42.028473+00:00 INFO kernel: [  328.527599] spi5.0: wakeup source activated, active_count=321
2018-01-02T20:35:42.077191+00:00 INFO kernel: [  328.575842] spi5.0: wakeup source activated, active_count=322
2018-01-02T20:35:42.122334+00:00 INFO kernel: [  328.621150] spi5.0: wakeup source activated, active_count=323
2018-01-02T20:35:42.183175+00:00 INFO kernel: [  328.681945] spi5.0: wakeup source activated, active_count=324
2018-01-02T20:35:42.260182+00:00 INFO kernel: [  328.758547] spi5.0: wakeup source activated, active_count=325
2018-01-02T20:35:42.279190+00:00 INFO kernel: [  328.777551] spi5.0: wakeup source activated, active_count=326
2018-01-02T20:35:42.354176+00:00 INFO kernel: [  328.852695] spi5.0: wakeup source activated, active_count=327
2018-01-02T20:35:42.457192+00:00 INFO kernel: [  328.955681] spi5.0: wakeup source activated, active_count=328
2018-01-02T20:35:42.532299+00:00 INFO kernel: [  329.031320] spi5.0: wakeup source activated, active_count=329
2018-01-02T20:35:42.596177+00:00 INFO kernel: [  329.094578] spi5.0: wakeup source activated, active_count=330
2018-01-02T20:35:42.633185+00:00 INFO kernel: [  329.132125] spi5.0: wakeup source activated, active_count=331
2018-01-02T20:35:42.669485+00:00 INFO kernel: [  329.168684] spi5.0: wakeup source activated, active_count=332
2018-01-02T20:35:42.753183+00:00 INFO kernel: [  329.252110] spi5.0: wakeup source activated, active_count=333
2018-01-02T20:35:42.826457+00:00 INFO kernel: [  329.325632] spi5.0: wakeup source activated, active_count=334
2018-01-02T20:35:42.933236+00:00 INFO kernel: [  329.432357] spi5.0: wakeup source activated, active_count=335
2018-01-02T20:35:43.000186+00:00 INFO kernel: [  329.498713] spi5.0: wakeup source activated, active_count=336
2018-01-02T20:35:43.024202+00:00 INFO kernel: [  329.522680] spi5.0: wakeup source activated, active_count=337
2018-01-02T20:35:43.069059+00:00 INFO kernel: [  329.568231] spi5.0: wakeup source activated, active_count=338
2018-01-02T20:35:43.089571+00:00 INFO kernel: [  329.588778] spi5.0: wakeup source activated, active_count=339
2018-01-02T20:35:43.112178+00:00 INFO kernel: [  329.611052] spi5.0: wakeup source activated, active_count=340
2018-01-02T20:35:43.173221+00:00 INFO kernel: [  329.671978] spi5.0: wakeup source activated, active_count=341
2018-01-02T20:35:43.244173+00:00 INFO kernel: [  329.743038] spi5.0: wakeup source activated, active_count=342
2018-01-02T20:35:43.262242+00:00 INFO kernel: [  329.761530] spi5.0: wakeup source activated, active_count=343
2018-01-02T20:35:43.368319+00:00 INFO kernel: [  329.866581] spi5.0: wakeup source activated, active_count=344
2018-01-02T20:35:43.404196+00:00 INFO kernel: [  329.903200] spi5.0: wakeup source activated, active_count=345
2018-01-02T20:35:43.483218+00:00 INFO kernel: [  329.981938] spi5.0: wakeup source activated, active_count=346
2018-01-02T20:35:43.521197+00:00 INFO kernel: [  330.019610] spi5.0: wakeup source activated, active_count=347
2018-01-02T20:35:43.575177+00:00 INFO kernel: [  330.073864] spi5.0: wakeup source activated, active_count=348
2018-01-02T20:35:43.656186+00:00 INFO kernel: [  330.154689] spi5.0: wakeup source activated, active_count=349
2018-01-02T20:35:43.670250+00:00 INFO kernel: [  330.169506] spi5.0: wakeup source activated, active_count=350
2018-01-02T20:35:44.020198+00:00 INFO kernel: [  330.518875] spi5.0: wakeup source activated, active_count=351
 
Cc: briannorris@chromium.org
Cc: rajatja@chromium.org
Cc: philipchen@chromium.org amstan@chromium.org
amstan noticed this too. I believe it's the keyboard. Perhaps the Bob EC is reporting keyboard wakeup events in S0, where Kevin isn't?
Cc: sha...@chromium.org
It's not obvious to me how these wakeup events are getting reported. Can someone grab the output of dump_stack() right after that "wakeup source activated" print?
Cc: dbasehore@chromium.org
Derek's noticing this on Kevin too
Shawn: I believe those are coming from ec_irq_thread() -> pm_wakeup_event() -> __pm_wakeup_event() -> wakeup_source_report_event() -> wakeup_source_activate()
So, Gru boards have this wakeup mask defined:

/* Define the MKBP events which are allowed to wakeup AP in S3. */
#define CONFIG_MKBP_WAKEUP_MASK \
                (EC_HOST_EVENT_MASK(EC_HOST_EVENT_LID_OPEN) |\
                 EC_HOST_EVENT_MASK(EC_HOST_EVENT_POWER_BUTTON) |\
                 EC_HOST_EVENT_MASK(EC_HOST_EVENT_KEY_PRESSED) |\
                 EC_HOST_EVENT_MASK(EC_HOST_EVENT_RTC))


which means that whenever any of those happen, we'll report a wakeup event in the kernel. Doesn't matter if we are actively resuming from S3, or if we're stably in S0 (and typing away at the keyboard).

Should the EC IRQ also be checking 'ec_dev->wake_enabled' before reporting a wakeup event?
Cc: gwendal@chromium.org
Cc: bleung@chromium.org
Labels: -Pri-3 M-65 Pri-2
It does seem a bit excessive.


Owner: rajatja@chromium.org
Status: Assigned (was: Untriaged)
I'm going to post a revert for now.  We can re-land when we can figure out a way for these things to be logged constantly while the device is not entering suspend.
Labels: M-64
The annoying patch made it into M-64 too.
Project Member

Comment 16 by bugdroid1@chromium.org, Jan 11 2018

Labels: merge-merged-chromeos-4.4
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/kernel/+/4d3ea038114e72ae905d53be645c3ee28f5ce91e

commit 4d3ea038114e72ae905d53be645c3ee28f5ce91e
Author: Douglas Anderson <dianders@chromium.org>
Date: Thu Jan 11 08:20:52 2018

Revert "CHROMIUM: pm/wakeup: log the wake source when activated"

This reverts commit d8a0de8cbb4a716a95775bf06dc71136a1f4fc30.

Reason for revert: This is way too much logging.  At least
looking at rk3399, this logs stuff almost constantly as a user
is typing and that's bad.  Before re-landing we'd want to enable
these logs only during suspend/resume cycles when they're useful.

Original change's description:
> CHROMIUM: pm/wakeup: log the wake source when activated
>
> Log a wakeup source that gets activated. This is useful to debug
> spurious wakes, suspend failures, and some other difficult to
> debug situations.
>
> Signed-off-by: Rajat Jain <rajatja@google.com>
>
> BUG=None
> TEST=verify wake on wifi is logged
>
> Change-Id: Ief7e61900dd3be144ded8ed38d48a9cc9ed2bf1d
> Reviewed-on: https://chromium-review.googlesource.com/724235
> Commit-Ready: Rajat Jain <rajatja@chromium.org>
> Tested-by: Rajat Jain <rajatja@chromium.org>
> Reviewed-by: Dmitry Torokhov <dtor@chromium.org>

BUG= chromium:798537 ,  chromium:784000 
TEST=Boot and no more spam

Change-Id: I48076fae775bd490f3f72ff54a2d0a7b140d22a0
Signed-off-by: Douglas Anderson <dianders@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/861173
Reviewed-by: Rajat Jain <rajatja@chromium.org>
Reviewed-by: Brian Norris <briannorris@chromium.org>

[modify] https://crrev.com/4d3ea038114e72ae905d53be645c3ee28f5ce91e/drivers/base/power/wakeup.c

Cc: bhthompson@chromium.org kbleicher@chromium.org
Labels: Merge-Request-64
Kevin / Bernie: I know this is very late for M-64, but it still might be worth considering.  Please come find me when you get in this morning.  Thanks!
Project Member

Comment 18 by sheriffbot@chromium.org, Jan 11 2018

Labels: -Merge-Request-64 Hotlist-Merge-Review Merge-Review-64
This bug requires manual review: We are only 11 days from stable.
Please contact the milestone owner if you have questions.
Owners: cmasso@(Android), cmasso@(iOS), kbleicher@(ChromeOS), abdulsyed@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
 dianders@, I'm in the Boulder office per #17.  Yep, very late for M-64.  Impact of not merging?
Inability to diagnose some kernel problems via feedback reports, because the logs are filled with keypress noise.
Labels: -Merge-Review-64 Merge-Approved-64
Reviewed with Dan on IM; compared prior / change to confirm a revert.  Comments are fair.  Approving for a M64 merge.
Project Member

Comment 22 by bugdroid1@chromium.org, Jan 11 2018

Labels: merge-merged-release-R64-10176.B-chromeos-4.4
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/kernel/+/6e1618e065fc43c33e6dcbcf764aa5a98ef9411d

commit 6e1618e065fc43c33e6dcbcf764aa5a98ef9411d
Author: Douglas Anderson <dianders@chromium.org>
Date: Thu Jan 11 21:00:16 2018

Revert "CHROMIUM: pm/wakeup: log the wake source when activated"

This reverts commit d8a0de8cbb4a716a95775bf06dc71136a1f4fc30.

Reason for revert: This is way too much logging.  At least
looking at rk3399, this logs stuff almost constantly as a user
is typing and that's bad.  Before re-landing we'd want to enable
these logs only during suspend/resume cycles when they're useful.

Original change's description:
> CHROMIUM: pm/wakeup: log the wake source when activated
>
> Log a wakeup source that gets activated. This is useful to debug
> spurious wakes, suspend failures, and some other difficult to
> debug situations.
>
> Signed-off-by: Rajat Jain <rajatja@google.com>
>
> BUG=None
> TEST=verify wake on wifi is logged
>
> Change-Id: Ief7e61900dd3be144ded8ed38d48a9cc9ed2bf1d
> Reviewed-on: https://chromium-review.googlesource.com/724235
> Commit-Ready: Rajat Jain <rajatja@chromium.org>
> Tested-by: Rajat Jain <rajatja@chromium.org>
> Reviewed-by: Dmitry Torokhov <dtor@chromium.org>

BUG= chromium:798537 ,  chromium:784000 
TEST=Boot and no more spam

Change-Id: I48076fae775bd490f3f72ff54a2d0a7b140d22a0
Signed-off-by: Douglas Anderson <dianders@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/861173
Reviewed-by: Rajat Jain <rajatja@chromium.org>
Reviewed-by: Brian Norris <briannorris@chromium.org>
(cherry picked from commit 4d3ea038114e72ae905d53be645c3ee28f5ce91e)
Reviewed-on: https://chromium-review.googlesource.com/862443

[modify] https://crrev.com/6e1618e065fc43c33e6dcbcf764aa5a98ef9411d/drivers/base/power/wakeup.c

Labels: -Hotlist-Merge-Review -Merge-Approved-64 Merge-Merged
Status: Fixed (was: Assigned)
Should be all good, then.  I'll leave it to Rajat to open another bug (if he wants) to re-land in a way that doesn't log so much.
We should still probably do something like me comment #8 cros_ec.c someday. We shouldn't be reporting wakeup events well after we've resumed. (That would, incidentally, also resolve the spamminess.)
Cc: derat@chromium.org
@24: IIRC, that's not quite right.  We still need to report wakeup events after we've resumed.  Let me see if I get this right:

1. When powerd decides it's time to suspend then it reads the wakeup count.

2. powerd goes through its standard procedure for suspending

3. powerd tells the kernel: go ahead and suspend as long as the wakeup count hasn't increased.


...thus the kernel _needs_ to keep increasing the wakeup count even when it's not aware that a suspend is coming.  +derat to keep me honest.

Comment 26 by derat@chromium.org, Jan 11 2018

I'm far from an expert on anything kernel-related, but here's my understanding:

1. powerd reads wakeup_count
2. powerd does pre-suspend stuff
3. powerd passes the count from step 1 to powerd_suspend
4. powerd_suspend *writes* that count back to wakeup_count, which:
   a) fails if more wakeup events have been received in the meantime, and
   b) primes the kernel for step 5, which is:
5. powerd_suspend writes "mem" (or whatever) to /sys/power/state, which
   fails deep in the kernel's suspend code if any wakeup events are received
   before the system has actually suspended (per the count written in step 4)

After writing that here, I see that it matches what I wrote long ago at https://chromium.googlesource.com/chromiumos/platform2/+/master/power_manager/docs/suspend_resume.md#wakeup-counts, so that's a good sign. :-)
FWIW, you've convinced me, Doug. So the wakeup event reports are WAI, and we just have to make the logging less annoying -- removing them entirely works too, but that's a big hammer :)

Sign in to add a comment