Bug 1557447 - Profiler support for IPC information; r=nika

This adds the ability to add profile markers for both the sender and recipient
sides of IPC messages. These can then be correlated with one another in the
profile visualization. For the UI component of this patch, see
<https://github.com/firefox-devtools/profiler/pull/2172>.

Differential Revision: https://phabricator.services.mozilla.com/D42226

--HG--
extra : moz-landing-system : lando
This commit is contained in:
Jim Porter 2019-10-17 23:39:42 +00:00
parent c5ea460d53
commit 641b95fb72
17 changed files with 252 additions and 19 deletions

View File

@ -283,13 +283,14 @@ add_task(async function() {
let markerData = m[dataCol];
if (
!markerData ||
markerData.category != "IPC" ||
markerData.interval != "start"
markerData.type != "IPC" ||
!markerData.sync ||
markerData.direction != "sending"
) {
continue;
}
markersForCurrentPhase.push(markerName);
markersForCurrentPhase.push(markerData.messageType);
}
}

View File

@ -16,7 +16,7 @@ prefs =
gfx.canvas.willReadFrequently.enable=true
environment =
MOZ_PROFILER_STARTUP=1
MOZ_PROFILER_STARTUP_FEATURES=js,mainthreadio
MOZ_PROFILER_STARTUP_FEATURES=js,mainthreadio,ipcmessages
MOZ_PROFILER_STARTUP_ENTRIES=10000000
[../browser_startup_mainthreadio.js]
[../browser_startup_content_mainthreadio.js]

View File

@ -186,6 +186,11 @@ const featureCheckboxes = [
value: "preferencereads",
title: "Track Preference Reads",
},
{
name: "IPC Messages",
value: "ipcmessages",
title: "Track IPC messages.",
},
{
name: "JS Allocations",
value: "jsallocations",

View File

@ -16,6 +16,8 @@ EXPORTS += [
'MediaSink.h'
]
include('/ipc/chromium/chromium-config.mozbuild')
FINAL_LIBRARY = 'xul'
if CONFIG['CC_TYPE'] in ('clang', 'gcc'):

View File

@ -46,4 +46,6 @@ include('/ipc/chromium/chromium-config.mozbuild')
MOCHITEST_MANIFESTS += [ 'tests/mochitest.ini' ]
include('/ipc/chromium/chromium-config.mozbuild')
FINAL_LIBRARY = 'xul'

View File

@ -35,6 +35,10 @@
using namespace mozilla::tasktracer;
#endif
#ifdef MOZ_GECKO_PROFILER
# include "ProfilerMarkerPayload.h"
#endif
// Undo the damage done by mozzconf.h
#undef compress
@ -1002,11 +1006,17 @@ bool MessageChannel::Send(Message* aMsg) {
return false;
}
if (msg->seqno() == 0) {
msg->set_seqno(NextSeqno());
}
MonitorAutoLock lock(*mMonitor);
if (!Connected()) {
ReportConnectionError("MessageChannel", msg.get());
return false;
}
AddProfilerMarker(msg.get(), MessageDirection::eSending);
SendMessageToLink(msg.release());
return true;
}
@ -1531,6 +1541,7 @@ bool MessageChannel::Send(Message* aMsg, Message* aReply) {
// msg will be destroyed soon, but name() is not owned by msg.
const char* msgName = msg->name();
AddProfilerMarker(msg.get(), MessageDirection::eSending);
SendMessageToLink(msg.release());
while (true) {
@ -1618,6 +1629,8 @@ bool MessageChannel::Send(Message* aMsg, Message* aReply) {
MOZ_RELEASE_ASSERT(reply->type() == replyType, "wrong reply type");
MOZ_RELEASE_ASSERT(reply->is_sync());
AddProfilerMarker(reply.get(), MessageDirection::eReceiving);
*aReply = std::move(*reply);
if (aReply->size() >= kMinTelemetryMessageSize) {
Telemetry::Accumulate(Telemetry::IPC_REPLY_SIZE,
@ -1668,6 +1681,9 @@ bool MessageChannel::Call(Message* aMsg, Message* aReply) {
msg->set_interrupt_remote_stack_depth_guess(mRemoteStackDepthGuess);
msg->set_interrupt_local_stack_depth(1 + InterruptStackDepth());
mInterruptStack.push(MessageInfo(*msg));
AddProfilerMarker(msg.get(), MessageDirection::eSending);
mLink->SendMessage(msg.release());
while (true) {
@ -1775,6 +1791,8 @@ bool MessageChannel::Call(Message* aMsg, Message* aReply) {
// this frame and return the reply.
mInterruptStack.pop();
AddProfilerMarker(&recvd, MessageDirection::eReceiving);
bool is_reply_error = recvd.is_reply_error();
if (!is_reply_error) {
*aReply = std::move(recvd);
@ -2087,6 +2105,7 @@ void MessageChannel::DispatchMessage(Message&& aMsg) {
IPC_LOG("DispatchMessage: seqno=%d, xid=%d", aMsg.seqno(),
aMsg.transaction_id());
AddProfilerMarker(&aMsg, MessageDirection::eReceiving);
{
AutoEnterTransaction transaction(this, aMsg);
@ -2125,6 +2144,8 @@ void MessageChannel::DispatchMessage(Message&& aMsg) {
if (reply && ChannelConnected == mChannelState) {
IPC_LOG("Sending reply seqno=%d, xid=%d", aMsg.seqno(),
aMsg.transaction_id());
AddProfilerMarker(reply.get(), MessageDirection::eSending);
mLink->SendMessage(reply.forget());
}
}
@ -2226,6 +2247,7 @@ void MessageChannel::DispatchInterruptMessage(ActorLifecycleProxy* aProxy,
MonitorAutoLock lock(*mMonitor);
if (ChannelConnected == mChannelState) {
AddProfilerMarker(reply.get(), MessageDirection::eSending);
mLink->SendMessage(reply.forget());
}
}
@ -2810,6 +2832,19 @@ void MessageChannel::DumpInterruptStack(const char* const pfx) const {
}
}
void MessageChannel::AddProfilerMarker(const IPC::Message* aMessage,
MessageDirection aDirection) {
#ifdef MOZ_GECKO_PROFILER
if (profiler_feature_active(ProfilerFeature::IPCMessages)) {
int32_t pid = mPeerPid == -1 ? base::GetCurrentProcId() : mPeerPid;
PROFILER_ADD_MARKER_WITH_PAYLOAD(
"IPC", IPC, IPCMarkerPayload,
(pid, aMessage->seqno(), aMessage->type(), mSide, aDirection,
aMessage->is_sync(), TimeStamp::Now()));
}
#endif
}
int32_t MessageChannel::GetTopmostMessageRoutingId() const {
MOZ_RELEASE_ASSERT(MessageLoop::current() == mWorkerLoop);
if (mCxxStackFrames.empty()) {

View File

@ -50,6 +50,11 @@ class RefCountedMonitor : public Monitor {
~RefCountedMonitor() {}
};
enum class MessageDirection {
eSending,
eReceiving,
};
enum class SyncSendError {
SendSuccess,
PreviousTimeout,
@ -463,6 +468,9 @@ class MessageChannel : HasResultCodes, MessageLoop::DestructionObserver {
// debugger with all threads paused.
void DumpInterruptStack(const char* const pfx = "") const;
void AddProfilerMarker(const IPC::Message* aMessage,
MessageDirection aDirection);
private:
// Called from both threads
size_t InterruptStackDepth() const {

View File

@ -627,11 +627,6 @@ inline bool LoggingEnabledFor(const char* aTopLevelProtocol) {
#endif
}
enum class MessageDirection {
eSending,
eReceiving,
};
MOZ_NEVER_INLINE void LogMessageForProtocol(const char* aTopLevelProtocol,
base::ProcessId aOtherPid,
const char* aContextDescription,

View File

@ -4742,14 +4742,9 @@ class _GenerateProtocolActorCode(ipdl.ast.Visitor):
+ [Whitespace.NL,
StmtDecl(Decl(Type.BOOL, sendok.name)),
StmtBlock([
StmtExpr(ExprCall(ExprVar('AUTO_PROFILER_TRACING'),
[ExprLiteral.String("IPC"),
ExprLiteral.String(self.protocol.name + "::" +
md.prettyMsgName()),
ExprVar('OTHER')])),
StmtExpr(ExprAssn(sendok, ExprCall(send,
args=[msgexpr,
ExprAddrOf(replyexpr)]))),
StmtExpr(ExprAssn(sendok, ExprCall(
send, args=[msgexpr, ExprAddrOf(replyexpr)]
))),
])
])
)

View File

@ -71,6 +71,9 @@
END_CATEGORY \
BEGIN_CATEGORY(DOM, "DOM", "blue") \
SUBCATEGORY(DOM, DOM, "Other") \
END_CATEGORY \
BEGIN_CATEGORY(IPC, "IPC", "lightgreen") \
SUBCATEGORY(IPC, IPC, "Other") \
END_CATEGORY
namespace JS {

View File

@ -39,7 +39,8 @@
"jsallocations",
"nostacksampling",
"nativeallocations",
"preferencereads"
"preferencereads",
"ipcmessages"
]
},
{

View File

@ -974,3 +974,53 @@ void NativeAllocationMarkerPayload::StreamPayload(
aUniqueStacks);
aWriter.IntProperty("size", mSize);
}
BlocksRingBuffer::Length IPCMarkerPayload::TagAndSerializationBytes() const {
return CommonPropsTagAndSerializationBytes() +
BlocksRingBuffer::SumBytes(mOtherPid, mMessageSeqno, mMessageType,
mSide, mDirection);
}
void IPCMarkerPayload::SerializeTagAndPayload(
BlocksRingBuffer::EntryWriter& aEntryWriter) const {
static const DeserializerTag tag = TagForDeserializer(Deserialize);
SerializeTagAndCommonProps(tag, aEntryWriter);
aEntryWriter.WriteObject(mOtherPid);
aEntryWriter.WriteObject(mMessageSeqno);
aEntryWriter.WriteObject(mMessageType);
aEntryWriter.WriteObject(mSide);
aEntryWriter.WriteObject(mDirection);
aEntryWriter.WriteObject(mSync);
}
// static
UniquePtr<ProfilerMarkerPayload> IPCMarkerPayload::Deserialize(
BlocksRingBuffer::EntryReader& aEntryReader) {
ProfilerMarkerPayload::CommonProps props =
DeserializeCommonProps(aEntryReader);
auto otherPid = aEntryReader.ReadObject<int32_t>();
auto messageSeqno = aEntryReader.ReadObject<int32_t>();
auto messageType = aEntryReader.ReadObject<IPC::Message::msgid_t>();
auto mSide = aEntryReader.ReadObject<ipc::Side>();
auto mDirection = aEntryReader.ReadObject<ipc::MessageDirection>();
auto mSync = aEntryReader.ReadObject<bool>();
return UniquePtr<ProfilerMarkerPayload>(
new IPCMarkerPayload(std::move(props), otherPid, messageSeqno,
messageType, mSide, mDirection, mSync));
}
void IPCMarkerPayload::StreamPayload(SpliceableJSONWriter& aWriter,
const TimeStamp& aProcessStartTime,
UniqueStacks& aUniqueStacks) const {
using namespace mozilla::ipc;
StreamCommonProps("IPC", aWriter, aProcessStartTime, aUniqueStacks);
aWriter.IntProperty("otherPid", mOtherPid);
aWriter.IntProperty("messageSeqno", mMessageSeqno);
aWriter.StringProperty("messageType",
IPC::StringFromIPCMessageType(mMessageType));
aWriter.StringProperty("side", mSide == ParentSide ? "parent" : "child");
aWriter.StringProperty("direction", mDirection == MessageDirection::eSending
? "sending"
: "receiving");
aWriter.BoolProperty("sync", mSync);
}

View File

@ -180,7 +180,10 @@ class Vector;
\
MACRO(16, "nativeallocations", NativeAllocations, \
"Collect the stacks from a smaller subset of all native " \
"allocations, biasing towards collecting larger allocations")
"allocations, biasing towards collecting larger allocations") \
\
MACRO(17, "ipcmessages", IPCMessages, \
"Have the IPC layer track cross-process messages")
struct ProfilerFeature {
# define DECLARE(n_, str_, Name_, desc_) \

View File

@ -16,6 +16,7 @@
#include "mozilla/UniquePtr.h"
#include "mozilla/Preferences.h"
#include "mozilla/UniquePtrExtensions.h"
#include "mozilla/ipc/ProtocolUtils.h"
#include "mozilla/net/TimingStruct.h"
#include "nsString.h"
@ -703,6 +704,43 @@ class NativeAllocationMarkerPayload : public ProfilerMarkerPayload {
int64_t mSize;
};
class IPCMarkerPayload : public ProfilerMarkerPayload {
public:
IPCMarkerPayload(int32_t aOtherPid, int32_t aMessageSeqno,
IPC::Message::msgid_t aMessageType, mozilla::ipc::Side aSide,
mozilla::ipc::MessageDirection aDirection, bool aSync,
const mozilla::TimeStamp& aStartTime)
: ProfilerMarkerPayload(aStartTime, aStartTime),
mOtherPid(aOtherPid),
mMessageSeqno(aMessageSeqno),
mMessageType(aMessageType),
mSide(aSide),
mDirection(aDirection),
mSync(aSync) {}
DECL_STREAM_PAYLOAD
private:
IPCMarkerPayload(CommonProps&& aCommonProps, int32_t aOtherPid,
int32_t aMessageSeqno, IPC::Message::msgid_t aMessageType,
mozilla::ipc::Side aSide,
mozilla::ipc::MessageDirection aDirection, bool aSync)
: ProfilerMarkerPayload(std::move(aCommonProps)),
mOtherPid(aOtherPid),
mMessageSeqno(aMessageSeqno),
mMessageType(aMessageType),
mSide(aSide),
mDirection(aDirection),
mSync(aSync) {}
int32_t mOtherPid;
int32_t mMessageSeqno;
IPC::Message::msgid_t mMessageType;
mozilla::ipc::Side mSide;
mozilla::ipc::MessageDirection mDirection;
bool mSync;
};
namespace mozilla {
// Serialize a pointed-at ProfilerMarkerPayload, may be null when there are no

View File

@ -9,5 +9,6 @@ support-files =
[browser_test_feature_jsallocations.js]
[browser_test_feature_preferencereads.js]
[browser_test_feature_nativeallocations.js]
[browser_test_feature_ipcmessages.js]
[browser_test_profile_single_frame_page_info.js]
[browser_test_profile_multi_frame_page_info.js]

View File

@ -0,0 +1,92 @@
/* This Source Code Form is subject to the terms of the Mozilla Public
* License, v. 2.0. If a copy of the MPL was not distributed with this
* file, You can obtain one at http://mozilla.org/MPL/2.0/. */
function countIPCMessagesInThread(thread) {
let count = 0;
for (let payload of getPayloadsOfType(thread, "PreferenceRead")) {
if (payload.prefName === "layout.css.dpi") {
count++;
}
}
return count;
}
/**
* Test the IPCMessage feature.
*/
add_task(async function test_profile_feature_ipcmessges() {
if (!AppConstants.MOZ_GECKO_PROFILER) {
return;
}
Assert.ok(
!Services.profiler.IsActive(),
"The profiler is not currently active"
);
startProfiler({ features: ["threads", "ipcmessages"] });
const url = BASE_URL + "fixed_height.html";
await BrowserTestUtils.withNewTab(url, async contentBrowser => {
const contentPid = await ContentTask.spawn(
contentBrowser,
null,
() => Services.appinfo.processID
);
info("Wait 100ms so that the tab finishes executing.");
await wait(100);
info(
"Check that some PreferenceRead profile markers were generated when " +
"the feature is enabled."
);
{
const { parentThread, contentThread } = await stopProfilerAndGetThreads(
contentPid
);
Assert.greater(
getPayloadsOfType(parentThread, "IPC").length,
0,
"IPC profile markers were recorded for the parent process' main " +
"thread when the IPCMessages feature was turned on."
);
Assert.greater(
getPayloadsOfType(contentThread, "IPC").length,
0,
"IPC profile markers were recorded for the content process' main " +
"thread when the IPCMessages feature was turned on."
);
}
startProfiler({ features: ["threads"] });
info("Now reload the tab with a clean run.");
gBrowser.reload();
await wait(100);
info(
"Check that no PreferenceRead markers were recorded when the " +
"feature is turned off."
);
{
const { parentThread, contentThread } = await stopProfilerAndGetThreads(
contentPid
);
Assert.equal(
getPayloadsOfType(parentThread, "IPC").length,
0,
"No IPC profile markers were recorded for the parent process' main " +
"thread when the IPCMessages feature was turned off."
);
Assert.equal(
getPayloadsOfType(contentThread, "IPC").length,
0,
"No IPC profile markers were recorded for the content process' main " +
"thread when the IPCMessages feature was turned off."
);
}
});
});

View File

@ -29,6 +29,8 @@ USE_LIBS += [
'jsoncpp',
]
include('/ipc/chromium/chromium-config.mozbuild')
FINAL_LIBRARY = 'xul-gtest'
if CONFIG['CC_TYPE'] in ('clang', 'gcc'):