brpc/src/bthread/task_tracer.cpp at master · apache/brpc · GitHub

History

463 lines (413 loc) · 17.4 KB

Raw

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

158

159

160

161

162

163

164

165

166

167

168

169

170

171

172

173

174

175

176

177

178

179

180

181

182

183

184

185

186

187

188

189

190

191

192

193

194

195

196

197

198

199

200

201

202

203

204

205

206

207

208

209

210

211

212

213

214

215

216

217

218

219

220

221

222

223

224

225

226

227

228

229

230

231

232

233

234

235

236

237

238

239

240

241

242

243

244

245

246

247

248

249

250

251

252

253

254

255

256

257

258

259

260

261

262

263

264

265

266

267

268

269

270

271

272

273

274

275

276

277

278

279

280

281

282

283

284

285

286

287

288

289

290

291

292

293

294

295

296

297

298

299

300

301

302

303

304

305

306

307

308

309

310

311

312

313

314

315

316

317

318

319

320

321

322

323

324

325

326

327

328

329

330

331

332

333

334

335

336

337

338

339

340

341

342

343

344

345

346

347

348

349

350

351

352

353

354

355

356

357

358

359

360

361

362

363

364

365

366

367

368

369

370

371

372

373

374

375

376

377

378

379

380

381

382

383

384

385

386

387

388

389

390

391

392

393

394

395

396

397

398

399

400

401

402

403

404

405

406

407

408

409

410

411

412

413

414

415

416

417

418

419

420

421

422

423

424

425

426

427

428

429

430

431

432

433

434

435

436

437

438

439

440

441

442

443

444

445

446

447

448

449

450

451

452

453

454

455

456

457

458

459

460

461

462

463

// Licensed to the Apache Software Foundation (ASF) under one

// or more contributor license agreements. See the NOTICE file

// distributed with this work for additional information

// regarding copyright ownership. The ASF licenses this file

// to you under the Apache License, Version 2.0 (the

// "License"); you may not use this file except in compliance

// with the License. You may obtain a copy of the License at

// http://www.apache.org/licenses/LICENSE-2.0

// Unless required by applicable law or agreed to in writing,

// software distributed under the License is distributed on an

// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY

// KIND, either express or implied. See the License for the

// specific language governing permissions and limitations

// under the License.

#ifdef BRPC_BTHREAD_TRACER

#include <inttypes.h>

#include <signal.h>

#include <unistd.h>

#include <poll.h>

#include <pthread.h>

#include <iomanip>

#include <gflags/gflags.h>

#include "bthread/task_tracer.h"

#include "bthread/processor.h"

#include "bthread/task_group.h"

#include "butil/fd_utility.h"

#include "butil/memory/scope_guard.h"

#include "butil/reloadable_flags.h"

#include "absl/debugging/stacktrace.h"

#include "absl/debugging/symbolize.h"

namespace bthread {

DEFINE_uint32(signal_trace_timeout_ms, 50, "Timeout for signal trace in ms");

BUTIL_VALIDATE_GFLAG(signal_trace_timeout_ms, butil::PositiveInteger<uint32_t>);

// Note that SIGURG handler may be registered by some library such as cgo

// so let the signal number be configurable

DEFINE_int32(signal_number_for_trace, SIGURG,

"signal number used for stack trace, default to SIGURG");

extern BAIDU_THREAD_LOCAL TaskMeta* pthread_fake_meta;

TaskTracer::SignalSync::~SignalSync() {

if (pipe_fds[0] >= 0) {

close(pipe_fds[0]);

}

if (pipe_fds[1] >= 0) {

close(pipe_fds[1]);

}

bool TaskTracer::SignalSync::Init() {

if (pipe(pipe_fds) != 0) {

PLOG(ERROR) << "Fail to pipe";

return false;

}

if (butil::make_non_blocking(pipe_fds[0]) != 0) {

PLOG(ERROR) << "Fail to make_non_blocking";

return false;

}

if (butil::make_non_blocking(pipe_fds[1]) != 0) {

PLOG(ERROR) << "Fail to make_non_blocking";

return false;

}

return true;

}

std::string TaskTracer::Result::OutputToString() const {

std::string str;

if (frame_count > 0) {

str.reserve(1024);

}

char symbol_name[128];

char unknown_symbol_name[] = "<unknown>";

if (frame_count > 0) {

for (size_t i = 0; i < frame_count; ++i) {

butil::string_appendf(&str, "#%zu 0x%016" PRIxPTR " ", i,

reinterpret_cast<uintptr_t>(ips[i]));

if (absl::Symbolize(ips[i], symbol_name, arraysize(symbol_name))) {

str.append(symbol_name);

} else {

str.append(unknown_symbol_name);

}

if (i + 1 < frame_count) {

str.push_back('\n');

}

} else {

str.append("No frame");

}

if (error) {

str.append("\nError message: ");

str.append(err_msg);

}

return str;

}

void TaskTracer::Result::OutputToStream(std::ostream& os) const {

char symbol_name[128];

char unknown_symbol_name[] = "<unknown>";

if (frame_count > 0) {

for (size_t i = 0; i < frame_count; ++i) {

os << "#" << i << " 0x"

<< std::hex << std::setw(16) << std::setfill('0')

<< reinterpret_cast<uintptr_t>(ips[i])

<< std::dec << std::setfill(' ') << " ";

if (absl::Symbolize(ips[i], symbol_name, arraysize(symbol_name))) {

os << symbol_name;

} else {

os << unknown_symbol_name;

}

if (i + 1 < frame_count) {

os << '\n';

}

} else {

os << "No frame";

}

if (error) {

os << "\nError message: " << err_msg;

}

bool TaskTracer::Init() {

if (_trace_time.expose("bthread_trace_time") != 0) {

LOG(ERROR) << "Fail to expose bthread_trace_time";

return false;

}

if (!RegisterSignalHandler()) {

return false;

}

// Warm up the libunwind.

unw_cursor_t cursor;

if (0 == unw_getcontext(&_context) && unw_init_local(&cursor, &_context) == 0) {

butil::ignore_result(TraceByLibunwind(cursor));

}

return true;

}

void TaskTracer::set_status(TaskStatus s, TaskMeta* m) {

CHECK_NE(TASK_STATUS_RUNNING, s) << "Use `set_running_status' instead";

CHECK_NE(TASK_STATUS_END, s) << "Use `set_end_status_unsafe' instead";

bool tracing = false;

{

BAIDU_SCOPED_LOCK(m->version_lock);

if (TASK_STATUS_UNKNOWN == m->status && TASK_STATUS_JUMPING == s) {

// Do not update status for jumping when bthread is ending.

return;

}

tracing = m->traced;

// bthread is scheduled for the first time.

if (TASK_STATUS_READY == s && nullptr == m->stack) {

m->status = TASK_STATUS_FIRST_READY;

} else {

m->status = s;

}

if (TASK_STATUS_CREATED == s) {

m->worker_tid = pthread_t{};

}

// Make sure bthread does not jump stack when it is being traced.

if (tracing && TASK_STATUS_JUMPING == s) {

WaitForTracing(m);

}

void TaskTracer::set_running_status(pthread_t worker_tid, TaskMeta* m) {

BAIDU_SCOPED_LOCK(m->version_lock);

m->worker_tid = worker_tid;

m->status = TASK_STATUS_RUNNING;

}

bool TaskTracer::set_end_status_unsafe(TaskMeta* m) {

m->status = TASK_STATUS_END;

return m->traced;

}

std::string TaskTracer::Trace(bthread_t tid) {

return TraceImpl(tid).OutputToString();

}

void TaskTracer::Trace(std::ostream& os, bthread_t tid) {

TraceImpl(tid).OutputToStream(os);

}

void TaskTracer::WaitForTracing(TaskMeta* m) {

BAIDU_SCOPED_LOCK(m->trace_lock);

// Acquiring trace_lock means tracing is done.

}

TaskTracer::Result TaskTracer::TraceImpl(bthread_t tid) {

butil::Timer timer(butil::Timer::STARTED);

BRPC_SCOPE_EXIT {

timer.stop();

_trace_time << timer.n_elapsed();

};

if (tid == bthread_self() ||

(nullptr != pthread_fake_meta && tid == pthread_fake_meta->tid)) {

return Result::MakeErrorResult("Forbid to trace self=%d", tid);

}

// Make sure only one bthread is traced at a time.

BAIDU_SCOPED_LOCK(_trace_request_mutex);

// The chance to remove unused SignalSyncs.

auto iter = std::remove_if(

_inuse_signal_syncs.begin(), _inuse_signal_syncs.end(),

[](butil::intrusive_ptr<SignalSync>& sync) {

return sync->ref_count() == 1;

});

_inuse_signal_syncs.erase(iter, _inuse_signal_syncs.end());

TaskMeta* m = TaskGroup::address_meta(tid);

if (nullptr == m) {

return Result::MakeErrorResult("bthread=%d never existed", tid);

}

BAIDU_SCOPED_LOCK(m->trace_lock);

TaskStatus status;

pthread_t worker_tid;

const uint32_t given_version = get_version(tid);

{

BAIDU_SCOPED_LOCK(m->version_lock);

if (given_version != *m->version_butex) {

return Result::MakeErrorResult("bthread=%d not exist now", tid);

}

status = m->status;

if (TASK_STATUS_UNKNOWN == status) {

return Result::MakeErrorResult("bthread=%d not exist now", tid);

} else if (TASK_STATUS_CREATED == status) {

return Result::MakeErrorResult("bthread=%d has just been created", tid);

} else if (TASK_STATUS_FIRST_READY == status) {

return Result::MakeErrorResult("bthread=%d is scheduled for the first time", tid);

} else if (TASK_STATUS_END == status) {

return Result::MakeErrorResult("bthread=%d has ended", tid);

} else if (TASK_STATUS_JUMPING == status) {

return Result::MakeErrorResult("bthread=%d is jumping stack", tid);

}

// Start tracing.

m->traced = true;

worker_tid = m->worker_tid;

}

BRPC_SCOPE_EXIT {

{

BAIDU_SCOPED_LOCK(m->version_lock);

// If m->status is BTHREAD_STATUS_END, the bthread also waits for

// tracing completion, so given_version != *m->version_butex is OK.

m->traced = false;

}

};

// The status may be RUNNING, SUSPENDED, or READY, which is traceable.

if (TASK_STATUS_RUNNING == status) {

return SignalTrace(worker_tid);

} else if (TASK_STATUS_SUSPENDED == status || TASK_STATUS_READY == status) {

return ContextTrace(m->stack->context);

}

return Result::MakeErrorResult("Invalid TaskStatus=%d of bthread=%d", status, tid);

}

// Instruct ASan to ignore this function.

BUTIL_ATTRIBUTE_NO_SANITIZE_ADDRESS

unw_cursor_t TaskTracer::MakeCursor(bthread_fcontext_t fcontext) {

unw_cursor_t cursor;

unw_init_local(&cursor, &_context);

auto regs = reinterpret_cast<uintptr_t*>(fcontext);

// Only need RBP, RIP, RSP on x86_64.

// The base pointer (RBP).

if (unw_set_reg(&cursor, UNW_X86_64_RBP, regs[6]) != 0) {

LOG(ERROR) << "Fail to set RBP";

}

// The instruction pointer (RIP).

if (unw_set_reg(&cursor, UNW_REG_IP, regs[7]) != 0) {

LOG(ERROR) << "Fail to set RIP";

}

#if UNW_VERSION_MAJOR >= 1 && UNW_VERSION_MINOR >= 7

// The stack pointer (RSP).

if (unw_set_reg(&cursor, UNW_REG_SP, regs[8]) != 0) {

LOG(ERROR) << "Fail to set RSP";

}

#endif

return cursor;

}

TaskTracer::Result TaskTracer::ContextTrace(bthread_fcontext_t fcontext) {

unw_cursor_t cursor = MakeCursor(fcontext);

return TraceByLibunwind(cursor);

}

TaskTracer::Result TaskTracer::TraceByLibunwind(unw_cursor_t& cursor) {

Result result;

while (result.frame_count < arraysize(result.ips)) {

int rc = unw_step(&cursor);

if (0 == rc) {

break;

} else if (rc < 0) {

return Result::MakeErrorResult("Fail to unw_step, rc=%d", rc);

}

unw_word_t ip = 0;

if (0 != unw_get_reg(&cursor, UNW_REG_IP, &ip)) {

continue;

}

result.ips[result.frame_count] = reinterpret_cast<void*>(ip);

++result.frame_count;

}

return result;

}

bool TaskTracer::RegisterSignalHandler() {

// Set up the signal handler.

_signal_num = FLAGS_signal_number_for_trace;

struct sigaction old_sa{};

struct sigaction sa{};

sa.sa_sigaction = SignalHandler;

sa.sa_flags = SA_SIGINFO;

sigfillset(&sa.sa_mask);

if (sigaction(_signal_num, &sa, &old_sa) != 0) {

PLOG(ERROR) << "Failed to sigaction";

return false;

}

if (nullptr != old_sa.sa_handler || nullptr != old_sa.sa_sigaction) {

LOG(ERROR) << "Signal handler of signal number "

<< _signal_num << " is already registered";

return false;

}

return true;

}

// Caution: This function should be async-signal-safety.

void TaskTracer::SignalHandler(int, siginfo_t* info, void* context) {

ErrnoGuard guard;

// Ref has been taken before the signal is sent, so no need to add ref here.

butil::intrusive_ptr<SignalSync> signal_sync(

static_cast<SignalSync*>(info->si_value.sival_ptr), false);

if (nullptr == signal_sync) {

// The signal is not from Tracer, such as TaskControl, do nothing.

return;

}

// Skip the first frame, which is the signal handler itself.

signal_sync->result.frame_count =

absl::DefaultStackUnwinder(signal_sync->result.ips, nullptr,

arraysize(signal_sync->result.ips),

1, context, nullptr);

// write() is async-signal-safe.

// Don't care about the return value.

butil::ignore_result(write(signal_sync->pipe_fds[1], "1", 1));

}

TaskTracer::Result TaskTracer::SignalTrace(pthread_t worker_tid) {

// CAUTION:

// https://github.com/gperftools/gperftools/wiki/gperftools'-stacktrace-capturing-methods-and-their-issues#libunwind

// Generally, libunwind promises async-signal-safety for capturing backtraces.

// But in practice, it is only partially async-signal-safe due to reliance on

// dl_iterate_phdr API, which is used to enumerate all loaded ELF modules

// (.so files and main executable binary). No libc offers dl_iterate_pdhr that

// is async-signal-safe. In practice, the issue may happen if we take tracing

// signal during an existing dl_iterate_phdr call (such as when the program

// throws an exception) or during dlopen/dlclose-ing some .so module.

// Deadlock call stack:

// #0 __lll_lock_wait (futex=futex@entry=0x7f0d3d7f0990 <_rtld_global+2352>, private=0) at lowlevellock.c:52

// #1 0x00007f0d3a73c131 in __GI___pthread_mutex_lock (mutex=0x7f0d3d7f0990 <_rtld_global+2352>) at ../nptl/pthread_mutex_lock.c:115

// #2 0x00007f0d38eb0231 in __GI___dl_iterate_phdr (callback=callback@entry=0x7f0d38c456a0 <_ULx86_64_dwarf_callback>, data=data@entry=0x7f0d07defad0) at dl-iteratephdr.c:40

// #3 0x00007f0d38c45d79 in _ULx86_64_dwarf_find_proc_info (as=0x7f0d38c4f340 <local_addr_space>, ip=ip@entry=139694791966897, pi=pi@entry=0x7f0d07df0498, need_unwind_info=need_unwind_info@entry=1, arg=0x7f0d07df0340) at dwarf/Gfind_proc_info-lsb.c:759

// #4 0x00007f0d38c43260 in fetch_proc_info (c=c@entry=0x7f0d07df0340, ip=139694791966897) at dwarf/Gparser.c:461

// #5 0x00007f0d38c44e46 in find_reg_state (sr=0x7f0d07defd10, c=0x7f0d07df0340) at dwarf/Gparser.c:925

// #6 _ULx86_64_dwarf_step (c=c@entry=0x7f0d07df0340) at dwarf/Gparser.c:972

// #7 0x00007f0d38c40c14 in _ULx86_64_step (cursor=cursor@entry=0x7f0d07df0340) at x86_64/Gstep.c:71

// #8 0x00007f0d399ed8f6 in GetStackTraceWithContext_libunwind (result=<optimized out>, max_depth=63, skip_count=132054887, ucp=<optimized out>) at src/stacktrace_libunwind-inl.h:138

// #9 0x00007f0d399ee083 in GetStackTraceWithContext (result=0x7f0d07df07b8, max_depth=63, skip_count=3, uc=0x7f0d07df0a40) at src/stacktrace.cc:305

// #10 0x00007f0d399ea992 in CpuProfiler::prof_handler (signal_ucontext=<optimized out>, cpu_profiler=0x7f0d399f6600, sig=<optimized out>) at src/profiler.cc:359

// #11 0x00007f0d399eb633 in ProfileHandler::SignalHandler (sig=27, sinfo=0x7f0d07df0b70, ucontext=0x7f0d07df0a40) at src/profile-handler.cc:530

// #12 <signal handler called>

// #13 0x00007f0d3a73c0b1 in __GI___pthread_mutex_lock (mutex=0x7f0d3d7f0990 <_rtld_global+2352>) at ../nptl/pthread_mutex_lock.c:115

// #14 0x00007f0d38eb0231 in __GI___dl_iterate_phdr (callback=0x7f0d38f525f0, data=0x7f0d07df10c0) at dl-iteratephdr.c:40

// #15 0x00007f0d38f536c1 in _Unwind_Find_FDE () from /lib/x86_64-linux-gnu/libgcc_s.so.1

// #16 0x00007f0d38f4f868 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1

// #17 0x00007f0d38f50a20 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1

// #18 0x00007f0d38f50f99 in _Unwind_RaiseException () from /lib/x86_64-linux-gnu/libgcc_s.so.1

// #19 0x00007f0d390088dc in __cxa_throw () from /lib/x86_64-linux-gnu/libstdc++.so.6

// #20 0x00007f0d3b5b2245 in __cxxabiv1::__cxa_throw (thrownException=0x7f0d114ea8c0, type=0x7f0d3d6dd830 <typeinfo for rockset::GRPCError>, destructor=<optimized out>) at /src/folly/folly/experimental/exception_tracer/ExceptionTracerLib.cpp:107

// Therefore, use async-signal-safe absl::DefaultStackUnwinder instead of libunwind.

if (pthread_equal(worker_tid, pthread_self())) {

return Result::MakeErrorResult("Forbid to trace self");

}

// Each signal trace has an independent SignalSync to

// prevent the previous SignalHandler from affecting the new SignalTrace.

butil::intrusive_ptr<SignalSync> signal_sync(new SignalSync());

if (!signal_sync->Init()) {

return Result::MakeErrorResult("Fail to init SignalSync");

}

// Add reference for SignalHandler.

signal_sync->AddRefManually();

sigval value{};

value.sival_ptr = signal_sync.get();

size_t sigqueue_try = 0;

while (pthread_sigqueue(worker_tid, _signal_num, value) != 0) {

if (errno != EAGAIN || sigqueue_try++ >= 3) {

// Remove reference for SignalHandler.

signal_sync->RemoveRefManually();

return Result::MakeErrorResult("Fail to pthread_sigqueue: %s", berror());

}

// Wait for the signal handler to complete.

butil::Timer timer;

if (FLAGS_signal_trace_timeout_ms > 0) {

timer.start();

}

pollfd poll_fd = {signal_sync->pipe_fds[0], POLLIN, 0};

// Wait for tracing to complete.

while (true) {

int timeout = -1;

if (FLAGS_signal_trace_timeout_ms > 0) {

timer.stop();

if (timer.m_elapsed() >= FLAGS_signal_trace_timeout_ms) {

return Result::MakeErrorResult("Timeout exceed %dms", FLAGS_signal_trace_timeout_ms);

}

timeout = (int64_t)FLAGS_signal_trace_timeout_ms - timer.m_elapsed();

}

// poll() is async-signal-safe.

// Self-pipe trick: https://man7.org/tlpi/code/online/dist/altio/self_pipe.c.html

int rc = poll(&poll_fd, 1, timeout);

if (-1 == rc) {

if (EINTR == errno) {

continue;

}

// Extend the lifetime of `signal_sync' to

// avoid it being destroyed in the signal handler.

_inuse_signal_syncs.push_back(signal_sync);

return Result::MakeErrorResult("Fail to poll: %s", berror());

}

break;

}

return signal_sync->result;

}

} // namespace bthread

#endif // BRPC_BTHREAD_TRACER

brpc/src/bthread/task_tracer.cpp at master · apache/brpc · GitHub

Uh oh!

Expand file tree

Breadcrumbs

task_tracer.cpp

Latest commit

History

Breadcrumbs

task_tracer.cpp

File metadata and controls