Open ranjitkrishnan opened 5 years ago
@ranjitkrishnan - did you provide the same name that you used in startTrackPage() for stopTrackPage(). You do not need to use trackPageView() if you are using startTrackPage() + stopTrackPage()
@jpiyali I might have messed up the name. After removing the trackPageView and calling startTrackPage and stopTrackPage(), i am getting things somewhat right. Do I need to set overridePageViewDuration as true in this usecase.
Currently my issue is that the pageView event is not starting from 0ms. It is starting somewhat in the middle as the screenshot below. The Dependencies are starting correctly.
overridePageViewDuration is to enable you to provide a manual measurement. The timeline depends on where you are firing the startPageView(). Are you firing this early enough in the page?
Also, overridePageViewDuration is applicable only to trackPageView() api
I am calling the startTrackPage on route change itself.
Isnt the PageViewDuration supposed to be the time interval between start and stop calls ?
What i am seeing is that the timeline start from the PageViewduration property. Say if the PageViewDuration is 1.5 sec, the timeline of the pageview call starts at 1.5 seconds and end at 3 seconds. Not sure if this observation is correct. See the screenshot below
@OsvaldoRosado - what is referenced as 0 in the graph above (is it earliest timeline for a specific set of related events?). For automatic pageview tracking, the telemetry is sent after; how do you capture start time of the page for this view above?
@ranjitkrishnan - yes this should be the time between start and stop page. From the screenshot, it looks like page view duration is being reported as 3.3 seconds which maps to time difference. So, two questions,
duration of page load is correct or not (this should be really when you fire off stoppagetrack) in the timeline, what is marked as time start. @OsvaldoRosado - please help how you define this.
The gantt chart sets 0 to the earliest start time in the operation (usually equal to the set of telemetry sharing an operation id, ignoring extenuating circumstances).
The transaction details view is aware of how different versions of different SDKs collect telemetry. For JS SDK, timestamps are adjusted for timeline purposes by subtracting duration from the telemetry time, to accommodate for #628
Additional note to above: It looks like this adjustment only happens for dependency telemetry from JS SDK. Should this happen for pageviews as well? The first screenshot in this thread doesn't look like adjustments are needed (unless those ajax calls should have happened after the end of the pageview event, not during)
@OsvaldoRosado The first screenshot in the thread was captured by calling trackPageView method which was giving wrong pageView duration for SPA as there is no page load here and was showing the same page view duration for all pages.
As suggested by @jpiyali , i have changed to use startTrackPage() and stopTrackPage() where i was calling startTrackPage on the route change and stop when the page is completely loaded after all the ajax calls. I am getting the duration correctly but it is not correctly positioning in the gantt chart.
@ranjitkrishnan Got it. I'm just trying to understand if the SDK behavior is such that a start time calculation adjustment needs to happen for all page views, or just ones recorded using start/stop. (And if the latter, how the UI is supposed to know this is the case). @jpiyali Any thoughts?
Referencing PR https://github.com/Microsoft/ApplicationInsights-JS/pull/804 to fix issue around dependency time tracking. Fix will be available only in Javascript SDK beta version 2.0.4
Hello All, Any update on this? Has this issue been fixed yet? as for one of our application which is SPA same issue With multiple user clicks within the application samething is getting reported back in Application Insights (attached screen shot), We are using trackPageView() method in the constructor of the App.component.ts so that every page gets reported. Anyhelp on this? Should we not use trackPageView() and instead use the startTrackPage and stopTrackPage?
not sure now this will be help full still, set the below property. and see overridePageViewDuration: true, autoTrackPageVisitTime: true and check in the customMetrix excel, the ms will be some what accurate.
the refUri is not capturing for me, any help ?
So, I've been having similar problems in an SPA, and decided to try to single-step the code that's built in version 2.2.2, and hosted in https://az416426.vo.msecnd.net/scripts/b/ai.2.js, I think I see the following:
trackPageView
currently accepts an object containing a request name, an optional url, and an optional properties objecttrackPageView
calculates a custom duration (in customDuration
) via the internal PageViewPerformanceManager class, which uses window.performance.timing
to get its duration. overridePageViewDuration
is set, a custom duration property based on the value calculated in 2.trackPageView
sends the pageView telemetry.trackPageView
sets a 100ms timeout (to let DOM settle down, presumably), after which it sends any performance telemetry it was able to collect. If this gets called AGAIN, because of another trackPageView
call, this timeout handler sends nothing, as it tracks whether or not it sent anything on this page load.EDIT: The example below is a good way to track page views backwards, it seems. I'm leaving it here so that you can see how broken it is, and my next attempt in the subsequent post.
So, trackPageView
looks to be fairly dependent on the idea of page loads, as opposed to Ajax content.
I was able to get the SDK to log correct durations (although the portal shows it as page load time, not duration), by putting the following into my base Razor view file:
@{
var userGuid = "";
var accountGuid = "";
if (User.Identity.IsAuthenticated)
{
var identity = (ClaimsIdentity) Thread.CurrentPrincipal.Identity;
var claim = identity.Claims.FirstOrDefault(x => x.Type == "User");
userGuid = claim?.Value;
var accountGuid = identity.Claims.FirstOrDefault(x => x.Type == "Account");
accountGuid = accountGuid ?.Value;
}
}
@if ((System.Configuration.ConfigurationManager.AppSettings["iKey"] ?? "").Length > 0) {
<text>
const appInsights = new Microsoft.ApplicationInsights.ApplicationInsights({
config: {
instrumentationKey: '@System.Configuration.ConfigurationManager.AppSettings["iKey"]'
}
});
</text>
}
else
{
<text>
const appInsights = null; // no app insights SDK without an iKey
</text>
}
if (appInsights) {
appInsights.loadAppInsights();
// track user and account
appInsights.setAuthenticatedUserContext('@userGuid', '@accountGuid');
// track the page load itself
appInsights.properties.context.telemetryTrace.traceID = '@Context.GetRequestTelemetry().Context.Operation.Id';
// sneak a property with a view start time
appInsights.properties.spaPageViewRefTime = new Date().getTime();
// and track it
appInsights.trackPageView({name: 'Accelerate', url: '/'});
}
And then the following at the beginning of the JS call that issues an Ajax call and loads the partial view with content:
var reqName = url.replace(baseUrl, "").split('?')[0];
var trackAsPageView = appInsights && (ajaxOptions.$partialViewTarget.attr("id") === "theIdOfTheContentIWantToTreatAsMy_Page_");
if (trackAsPageView) {
let aiProps = appInsights.properties;
// calculate the duration
let pageViewDuration = new Date().getTime() - aiProps.spaPageViewRefTime;
// track it
appInsights.trackPageView({ name: reqName, uri: url, properties: { duration: pageViewDuration } });
// reset the page duration timer
aiProps.spaPageViewRefTime = new Date().getTime();
// and get a new operation ID, so that the whole session isn't collected in one place
aiProps.context.telemetryTrace.traceID = getNewApplicationInsightsId();
aiProps.context.telemetryTrace.name = reqName;
}
I lifted the trace ID code out of the SDK implementation, as it's private, and exposed it in a helper function:
function getNewApplicationInsightsId(): string {
var hexValues = ["0", "1", "2", "3", "4", "5", "6", "7", "8", "9", "a", "b", "c", "d", "e", "f"];
// rfc4122 version 4 UUID without dashes and with lowercase letters
var oct = "", tmp;
for (var a = 0; a < 4; a++) {
tmp = (0x100000000 * Math.random()) | 0;
oct +=
hexValues[tmp & 0xF] +
hexValues[tmp >> 4 & 0xF] +
hexValues[tmp >> 8 & 0xF] +
hexValues[tmp >> 12 & 0xF] +
hexValues[tmp >> 16 & 0xF] +
hexValues[tmp >> 20 & 0xF] +
hexValues[tmp >> 24 & 0xF] +
hexValues[tmp >> 28 & 0xF];
}
// "Set the two most significant bits (bits 6 and 7) of the clock_seq_hi_and_reserved to zero and one, respectively"
var clockSequenceHi = hexValues[8 + (Math.random() * 4) | 0];
return oct.substr(0, 8) + oct.substr(9, 4) + "4" + oct.substr(13, 3) + clockSequenceHi + oct.substr(16, 3) + oct.substr(19, 12);
}
Sorry for the wall of text, but I AM seeing correct durations with this using trackPageView. I believe based on this that startTrackPage and stopTrackPage would be a better solution for SPAs, as they seem to be much lighter weight. Hope this is helpful.
OK. So, I "solved" the problem in reverse in my previous post. I have to play fewer games with squirreling values away, and get better metrics, if I do this:
In my .cshtml base, bookend the page with a startTrackPage
in <head>
, and a stopTrackPage
in $(document).ready
:
const appInsights = new Microsoft.ApplicationInsights.ApplicationInsights({
config: {
instrumentationKey: '@System.Configuration.ConfigurationManager.AppSettings["iKey"]',
autoTrackPageVisitTime: true
}
});
if (appInsights) {
appInsights.loadAppInsights();
appInsights.setAuthenticatedUserContext('@userGuid', '@bpGuid');
appInsights.properties.context.telemetryTrace.traceID = '@Context.GetRequestTelemetry().Context.Operation.Id';
appInsights.startTrackPage('/');
}
and
$(document).ready(function () {
...
if (appInsights) { appInsights.stopTrackPage('/', window.location); }
});
In my Ajax helper, before submitting the request:
let reqName = url.replace(baseUrl, "").split('?')[0];
let trackAsPageView = appInsights && (ajaxOptions.$divToUpdateSelector.attr("id") === "myPageViewTargetId");
let pageViewRefTime = new Date().getTime();
if (trackAsPageView) {
let aiProps = appInsights.properties;
// This is needed to let each page view have independent transaction details in the
// end-to-end transaction view, but it's troublesome for things that come later
// like tracking the PREVIOUS page visit time
**aiProps.context.telemetryTrace.traceID = getNewApplicationInsightsId();
aiProps.context.telemetryTrace.name = reqName;**
appInsights.startTrackPage(reqName);
}
And in my request complete handler:
if (trackAsPageView) {
let pageViewDuration = new Date().getTime() - pageViewRefTime;
let memory = window && window.performance && window.performance['memory']
? window.performance['memory']
: { totalJSHeapSize: "0", usedJSHeapSize: "0" };
let _1mb = 1024.00 * 1024.00;
appInsights.stopTrackPage(reqName, url,
{
duration: pageViewDuration,
totalJS: (memory.totalJSHeapSize / _1mb).toLocaleString('en-US') + "MB",
usedJS: (memory.usedJSHeapSize / _1mb).toLocaleString('en-US') + "MB"
});
So, I get good page loads/durations out of App Insights now! I also get PageVisitTime
metrics recorded!
Here's the problem, though: Changing the traceID, as the docs suggest for SPAs, works brilliantly for separating details of different page views. And when you stop tracking a view, the SDK logs a metric for the PREVIOUS page visit time - great - the problem is the previous view was loaded on a different traceID, and you've changed it for the current view, so it gets logged as the operation ID of the PageVisitTime metric. In other words, the metric will be correct based on request name and URL, but if you try to correlate it based on operationID, it will align with the SUBSEQUENT page view, because you changed it.
Or am I doing this wrong, also? It's hard to tell. I'm not using Angular or React plugins, because we're not using a formal SPA framework.
I like this SDK, but it feels a little broken for SPAs at the present time. I'll have to go back and basically implement my own PageVisitTime tracker in order to get metrics that line up.
And, once again, I apologize for the wall of text. I think, though, that it's important to see the thought process of ordinary developers like myself, because documentation and examples live in multiple pages (GitHub, as well as docs.microsoft.com), they're not always current, and folks like me wind up having to reverse-engineer the documentation from the code.
And, I'm back. I think this solves the problem "correctly" for my use case. No wall of text. Just the changes. I am hijacking appInsights.properties to track my own "previous view".
View
: disable page visit tracking, and start tracking the page:const appInsights = new Microsoft.ApplicationInsights.ApplicationInsights({
config: {
instrumentationKey: '@System.Configuration.ConfigurationManager.AppSettings["iKey"]',
autoTrackPageVisitTime: false
}
});
if (appInsights) {
appInsights.loadAppInsights();
appInsights.properties.context.telemetryTrace.traceID = '@Context.GetRequestTelemetry().Context.Operation.Id';
appInsights.startTrackPage('/');
}
View $(document).ready:
$(document).ready(function () {
if (appInsights) {
// track the current view
appInsights.properties.spaPageVisitRef = {
refTime: new Date().getTime(),
uri: window.location,
name: '/'
};
appInsights.stopTrackPage('/', window.location);
}
});
Ajax request setup:
let reqName = url.replace(baseUrl, "").split('?')[0];
let trackAsPageView = appInsights && (ajaxOptions.$divToUpdateSelector.attr("id") === "MyViewTarget");
let pageViewRefTime = new Date().getTime();
// If we're loading the main content view that represents a "page"
if (trackAsPageView) {
let aiProps = appInsights.properties;
// If another request reference is stored on the App Insights properties object,
// then that is the previous page view for PageVisitTime tracking purposes.
// Calculate the timespan, and track it as the PageVisitTime metric
if (aiProps.spaPageVisitRef) {
let properties = { PageName: aiProps.spaPageVisitRef.name, PageUrl: aiProps.spaPageVisitRef.uri };
let pageVisitTime = new Date().getTime() - aiProps.spaPageVisitRef.refTime;
appInsights.trackMetric({
name: "PageVisitTime",
average: pageVisitTime,
max: pageVisitTime,
min: pageVisitTime,
sampleCount: 1
}, properties);
}
// Change the trace ID, so that this page view, and all requests that fall within it,
// are tracked independently of other page views. This more or less simulates
// the page lifecycle on which the SDK operates.
aiProps.context.telemetryTrace.traceID = getNewApplicationInsightsId();
aiProps.context.telemetryTrace.name = reqName;
// Start tracking the new "page".
appInsights.startTrackPage(reqName);
}
Ajax request complete:
if (trackAsPageView) {
// Calculate tracking properties
let pageViewDuration = new Date().getTime() - pageViewRefTime;
let memory = window && window.performance && window.performance['memory']
? window.performance['memory']
: { totalJSHeapSize: "0", usedJSHeapSize: "0" };
let _1mb = 1024.00 * 1024.00;
// Record telemetry for the completed request
appInsights.stopTrackPage(reqName, url,
{
duration: pageViewDuration,
totalJS: (memory.totalJSHeapSize / _1mb).toLocaleString('en-US') + "MB",
usedJS: (memory.usedJSHeapSize / _1mb).toLocaleString('en-US') + "MB"
});
// Start PageVisitTime tracking for this view
appInsights.properties.spaPageVisitRef = {
refTime: new Date().getTime(),
uri: url,
name: reqName
};
}
We were having issues with pageview where its "eventTime" in appinsights was actually the end of the event, while in dotnet core appinsights the eventTime seems to be the start of the event.. I tested this by setting the startTime of a dependency telemetry manually with the correct value with a matching pageView request.
Here B is the correct time, since it aligns with the backend services timestamps, while A is the incorrect pageview time which is perfectly off by its duration.
Managed to fix this by adding a TelemetryInitializer and overriding the .startTime property to follow the AJAX codepath shown as resolved for this issue https://github.com/microsoft/ApplicationInsights-JS/issues/628.
appInsights.addTelemetryInitializer(TelemetryInitializer);
const setStartTimeToCorrectValue = (envelope: ITelemetryItem, duration: number) => {
const newStartTime = new Date((new Date(envelope.time) as any) - duration);
envelope.baseData.startTime = newStartTime;
envelope.time = newStartTime.toISOString();
};
export default (envelope: ITelemetryItem) => {
if (envelope.baseType === 'RemoteDependencyData' && envelope.baseData.duration) {
const duration = envelope.baseData.duration;
setStartTimeToCorrectValue(envelope, duration);
} else if (envelope.baseType === 'PageviewData' && envelope.data.duration) {
const duration = envelope.data.duration;
setStartTimeToCorrectValue(envelope, duration);
}
};
Note that I also overrode dependency values, since the auto tracking of FETCH calls were also wrong for us. They would start in appinsights a duration time after what our downstream services reported.
@mRowlinson27 VERY nice find... I've created a new issue for this specific bug.
I am having the same problem with latest library @microsoft/applicationinsights-web 2.7.2.
I am calling startTrackPage at 2021-12-13T03:46:27.423Z and calling stopTrackPage at 2021-12-13T03:46:40.206Z. The loading time of the page is 12.8 seconds. In my telemetry initializer I am logging envelope.time and it's set to 2021-12-13T03:46:40.206Z. I tried to manually override the time in my telemetry initializer to 2021-12-13T03:46:27.423Z, however when I inspect the network packets, the envelope is sent with time set to 2021-12-13T03:46:40.207Z (which is also reported as the event time when I check on azure portal).
This causes the page load to show up after the rest of the requests:
Another round of testing with:
duration: "12205"
startTrackPage: 2021-12-13T04:43:02.194Z
stopTrackPage: 2021-12-13T04:43:14.399Z
set envelope.time to 2021-12-13T04:42:49.989Z in the telemetry initializer (to check if deducting the duration from startTrackPage shows up correctly)
debugger was paused in this testing for about 1 min
in network tab I can see the pageview sent with envelope.time 2021-12-13T04:43:59.542Z
in azure portal the event shows up as 2021-12-13T04:43:59.542Z
This confirms envelope.time is being set to whenever the telemetry info is sent to azure, and that's why it's always wrong. For me fix mentioned above doesn't work as the time value get overwritten in the sdk before being sent.
update
So after further testing I decided to go with this approach: instead of calling startTrackPage, start a new operation, store timestamp instead of calling stopTrackPage, call trackPageView with a calculated duration follow logic above to subtract duration from envelope.time, as trackPageView does allow the time property to be set in the telemetry initializer.
trackPageView({
uri,
refUri,
properties: {
duration: dateNow() - this.startTime
}
});
Hi @h0wXD, looking at your workaround and the actual code for the stopTrackPage
they appear to be doing the same thing...
Where the stopTrackPage
calls the stop
action on the _pageTiming
which calls the defined action that is calling sendPageViewInternal()
which is what the trackPageView
(eventually calls) with the duration
properties set...
And in both cases the envelope.time
is the time of the event -- am I missing something subtle here? As apart from the breakpoint in the debugger (which would have the same effect -- depending on where you stop) I'm thinking the start/stop PageView with no telemetryInitializer adjustment should be doing the same thing???
RE: @h0wXD and for others I am calling startTrackPage at 2021-12-13T03:46:27.423Z and calling stopTrackPage at 2021-12-13T03:46:40.206Z. The loading time of the page is 12.8 seconds. In my telemetry initializer I am logging envelope.time and it's set to 2021-12-13T03:46:40.206Z. I tried to manually override the time in my telemetry initializer to 2021-12-13T03:46:27.423Z, however when I inspect the network packets, the envelope is sent with time set to 2021-12-13T03:46:40.207Z (which is also reported as the event time when I check on azure portal).
if you try setting envelop.time in a telemetry initializer it will get overwritten. but in the telemetry initializer you can set startTime
on the baseData and this will update the envelop.time
sdk.addTelemetryInitializer(function (envelope) {
if (envelope.baseType == "PageviewData") {
envelope.baseData.startTime = new Date(performance.timeOrigin);
}
});
Thanks @pl-jcarter that is a REALLY good catch!!! -- BUT!!!
We recently (Monday Feb 7, 2022) identified a change with the backed "Portal" that "stopped" adjusting the envelope.time for the PageView (to "fix" the reported time) by the duration (effectively subtracting the duration from the envelope.time) based on the version of the SDK being used.
startTime
for the envelope and applied a change for dependencies (ajax requests only) to internally adjust the envelope.time so if present this would be used. startTime
does actually work for any event, but it only automatically populated for dependencies.So a couple of things are now in progress.
startTime
"fix" above, in which case the reported PageView will be further "reduced" by the duration
. Which means the only solution for those how are using the telemetryInitializer "fix" will need to undo the "fix".startTime
to the PageView events (indirectly causing the "fix" and "issue"), BUT this will be synchronized with the Portal so rather than internally adjusting based on version 2.5.7 it will use whatever the new version of the SDK that includes that change (at least this is the current plan). Hello everyone, I'm using version: 2.8.1 in a spa written with angular 13.3.0.
Using the configuration:
To get around the problem, i disabled the enableAutoRouteTracking and started using the function: startTrackPage and stopTrackPage.
this.router.events
.subscribe((event) => {
switch (true) {
case event instanceof NavigationStart:
const converted = (event as NavigationStart);
this.appInsights.startTrackPage(converted.url);
this.appInsights.context.telemetryTrace.name = converted.url;
break;
case event instanceof NavigationEnd:
case event instanceof NavigationCancel:
case event instanceof NavigationError:
const error = (event as NavigationEnd | NavigationCancel | NavigationError);
this.appInsights.stopTrackPage(error.url);
this.appInsights.flush();
break;
}
});
however I noticed a behavior where the operation_name was coming invalid, it always came the name of the first page accessed, example below:
As the overview screen aggregates by the property (operation_Name) the display was wrong, to work around the problem in addition to calling the function: startTrackPage I also needed to set the name of the operation:
this.appInsights.context.telemetryTrace.name = converted.url;
That way, I managed to get around it and apparently everything is working perfectly.
But I have a question, shouldn't the name of the operation_Name property take into account the value of the name that we set in the method call (startTrackPage)?
The stopTrackPage takes 2 arguments that are key
_self.stopTrackPage = (name?: string, url?: string, properties?: { [key: string]: string }, measurement?: { [key: string]: number }) => {
The name
is really the document.title and also used as a key
for the internal tracking of the timings.
So I think if you pass the url as the 2nd argument (as well) this should work https://github.com/microsoft/ApplicationInsights-JS/blob/master/extensions/applicationinsights-analytics-js/src/JavaScriptSDK/AnalyticsPlugin.ts#L376-L396
@MSNev I tried using the second parameter and it didn't work either, the only way I found was as in the example above.
@Karlie-777 can you please investigate this a bit more as I believe the start / stop should work in this case and please provide any other context you have for tracking page view times for SPA's
@renandegrandi If I am understanding it correctly, you are mentioning that operation_Name
is not auto-adjusted for SPA. Our applicationInsights evaluates operation_name
based on location path which does not work for SPA. Therefore you have to manuallly adjust it. But you can also adjust it by using telemetryInitializer
https://github.com/microsoft/ApplicationInsights-JS#:~:text=Session%20information-,Telemetry%20Initializers,-Telemetry%20initializers%20are
@Karlie-777 I understand your position, and in fact it will solve the problem, but you don't believe if we are identifying the operation through the parameter this.appInsights.startTrackPage(name: string);
can't we assume that the operation name is the name we're entering in the startTrackPage
?
@renandegrandi The name
parameter in startTrackPage
can be customized and can be any string. Therefore, if we assume the operation_name
is the name
in startTrackPage
, it might cause some issues since operation_name
is used for finding all the telemetry items for a group of operations.
@Karlie-777 I don't think this can cause problems, because I use the insights sdk for workerservices, and in it we can provide the name of the operation through the method: using (telemetryClient.StartOperation<RequestTelemetry>("operation"))
, where the operation is a string.
Based on this information, I believe we would have no problem, but I understand your point.
@renandegrandi so the StartOperation
in azure monitor sdk is a helper method to support correlation (it creates a 'container' for nested operations) which is different from appInsights startTrackPage
(this api is only used for pageview). If you have any ideas on adding the similar wrapper for appInsights Angular plugin, we would love your contributions😊 repo: https://github.com/microsoft/applicationinsights-angularplugin-js
We are using Application Insights to instrument an Angular 6 SPA. In route change, we are calling trackPageView. But the same duration is shown in all the pages. I have seen a similar issue raised before for this https://github.com/Microsoft/ApplicationInsights-JS/issues/570
I tried using startTrackPage() and stopTrackPage() method as per that suggestion. But i am confused on the usage of this method. Do i need to still call trackPageView() method when calling start and stop method.
When calling start and stop methods, without using trackPageView, i didnt get an page view tracking. When used with trackPageView(), it came as another pageView entry within the main event as the screenshot below.
I may be doing something wrong here. Can you please let me know on how to use this.