1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
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
|
---
breadcrumbs:
- - /developers
- For Developers
- - /developers/design-documents
- Design Documents
page_name: download
title: Download
---
**Diagnose download issues**
Download used to use NetLog for logging purpose, as it is considered part of the
network operation. With network servicification, NetLog will no longer be
accessible outside the network process. As a result, download is switching to
TraceEvent for logging.
# Netlog format (this is deprecated)
For a DownloadItem, its netlog looks like this:
#### 21571799: DOWNLOAD
#### gzip-1.3.9.tar
Start Time: 2017-11-06 11:36:31.319
t=81821 \[st= 0\] +DOWNLOAD_ITEM_ACTIVE \[dt=539\]
--> danger_type = "NOT_DANGEROUS"
--> file_name = "gzip-1.3.9.tar"
--> final_url = "http://ftp.gnu.org/gnu/gzip/gzip-1.3.9.tar"
--> has_user_gesture = true
--> id = "3640"
--> original_url = "http://ftp.gnu.org/gnu/gzip/gzip-1.3.9.tar"
--> start_offset = "0"
--> type = "NEW_DOWNLOAD"
t=81821 \[st= 0\] DOWNLOAD_URL_REQUEST
--> source_dependency = 21571791 (URL_REQUEST)
t=81822 \[st= 1\] DOWNLOAD_FILE_CREATED
--> source_dependency = 21571800 (DOWNLOAD_FILE)
t=81825 \[st= 4\] DOWNLOAD_ITEM_UPDATED
--> bytes_so_far = "0"
t=81833 \[st= 12\] DOWNLOAD_ITEM_SAFETY_STATE_UPDATED
--> danger_type = "MAYBE_DANGEROUS_CONTENT"
t=81865 \[st= 44\] DOWNLOAD_ITEM_RENAMED
--> new_filename = "/usr/local/google/home/qinmin/Downloads/Unconfirmed
246585.crdownload"
--> old_filename = ""
t=82304 \[st=483\] DOWNLOAD_ITEM_UPDATED
--> bytes_so_far = "1648640"
t=82305 \[st=484\] DOWNLOAD_ITEM_UPDATED
--> bytes_so_far = "1648640"
t=82360 \[st=539\] DOWNLOAD_ITEM_RENAMED
--> new_filename = "/usr/local/google/home/qinmin/Downloads/gzip-1.3.9.tar"
--> old_filename = "/usr/local/google/home/qinmin/Downloads/Unconfirmed
246585.crdownload"
t=82360 \[st=539\] DOWNLOAD_ITEM_COMPLETING
--> bytes_so_far = "1648640"
--> final_hash =
"A08ABC68B607A70450930E698A90A0C30C81CE45A656CC47D2B89CA87C059DF6"
t=82360 \[st=539\] DOWNLOAD_ITEM_FINISHED
--> auto_opened = "no"
For a DownloadFile, it looks like:
#### 21571800: DOWNLOAD_FILE
Start Time: 2017-11-06 11:36:31.320
t=81822 \[st= 0\] +DOWNLOAD_FILE_ACTIVE \[dt=538\]
--> source_dependency = 21571799 (DOWNLOAD)
t=81822 \[st= 0\] +DOWNLOAD_FILE_OPENED \[dt=43\]
--> file_name =
"/usr/local/google/home/qinmin/.local/share/.com.google.Chrome.pzFBTU"
--> start_offset = "0"
t=81822 \[st= 0\] DOWNLOAD_STREAM_DRAINED
--> num_buffers = 0
--> stream_size = 0
t=81865 \[st= 43\] -DOWNLOAD_FILE_OPENED
t=81865 \[st= 43\] DOWNLOAD_FILE_RENAMED \[dt=0\]
--> new_filename = "/usr/local/google/home/qinmin/Downloads/Unconfirmed
246585.crdownload"
--> old_filename =
"/usr/local/google/home/qinmin/.local/share/.com.google.Chrome.pzFBTU"
t=81865 \[st= 43\] +DOWNLOAD_FILE_OPENED \[dt=493\]
--> file_name = "/usr/local/google/home/qinmin/Downloads/Unconfirmed
246585.crdownload"
--> start_offset = "0"
t=81883 \[st= 61\] DOWNLOAD_FILE_WRITTEN \[dt=0\]
--> bytes = "2262"
…...
t=82304 \[st=482\] DOWNLOAD_FILE_WRITTEN \[dt=0\]
--> bytes = "2582"
t=82358 \[st=536\] -DOWNLOAD_FILE_OPENED
t=82358 \[st=536\] DOWNLOAD_STREAM_DRAINED
--> num_buffers = 2
--> stream_size = 10898
t=82359 \[st=537\] DOWNLOAD_FILE_RENAMED \[dt=0\]
--> new_filename = "/usr/local/google/home/qinmin/Downloads/gzip-1.3.9.tar"
--> old_filename = "/usr/local/google/home/qinmin/Downloads/Unconfirmed
246585.crdownload"
t=82359 \[st=537\] DOWNLOAD_FILE_ANNOTATED \[dt=0\]
t=82360 \[st=538\] DOWNLOAD_FILE_DETACHED
t=82360 \[st=538\] -DOWNLOAD_FILE_ACTIVE
# Collect trace event
To start tracing, open Chrome and type in chrome://tracing in the URL bar, Click
on the record button and click on the “Edit Categories” button, check the
“download” category and uncheck all other categories, then hit the record
button.
# Migrating to Trace Event
With trace event, we still want to group most of the file operations and
download events under the same download. Otherwise, it will be hard to analyze
the trace if multiple downloads are on going. The downloadId is passed from
DownloadItem to DownloadFile, so it could be used to group all the nestable
events.
Because DownloadFile and DownloadItem live on different thread, DownloadFile’s
trace may outlive DownloadFile’s although the former is created later. As a
result, we will still keep the DownloadFile and DownloadItem events into
separate nestable groups.
Trace event is thread based, so instant events will not be grouped to into any
nestable events. A possible solution is to make any instant events a nestable
async events, but that doesn’t seems very necessary.
The trace event will contain all the information captured by the previous
NetLog, and will be shown in the following format:
<img alt="image"
src="https://docs.google.com/a/google.com/drawings/d/sGXr-eMkBNj31sftVEkr-7A/image?w=595&h=127&rev=33&ac=1&fmt=svg"
height=127 width=595>
As see in the graph, most of the download file events are grouped under
DownloadFileActive group. Instant events doesn’t belong to any group, and could
take place on different threads.
Events under DownloadFileActive include DownloadFileOpen and DownloadFileWrite.
Events under CrBrowserMain include most of the DownloadItem event, such as
DownloadStarted, DownloadItemUpdated, DownloadItemInterrupted,
DownloadItemCancelled, DownloadItemRenamed, DownloadItemSafetyStateUpdated,
DownloadItemCompleting, DownloadItemFinished and DownloadFileCreated event.
There could be multiple TaskScheduler threads for the write to happen. So events
like DownloadStreamDrained, DownloadFileRename, DownloadFileAnnotate,
DownloadFileDetached.
|
