Skip to content

Commit 096d8fa

Browse files
cmagliecmaglie
committed
Tracing for Library Discovery
1 parent 35d8e80 commit 096d8fa

File tree

3 files changed

+41
-14
lines changed

3 files changed

+41
-14
lines changed

‎internal/arduino/builder/internal/detector/cache.go‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@ import (
2121

2222
"github.com/arduino/arduino-cli/internal/arduino/builder/internal/runner"
2323
"github.com/arduino/go-paths-helper"
24+
"github.com/sirupsen/logrus"
2425
)
2526

2627
type detectorCache struct {
@@ -51,6 +52,13 @@ func (e *detectorCacheEntry) String() string {
5152
return "No operation"
5253
}
5354

55+
func (e *detectorCacheEntry) LogMsg() string {
56+
if e.CompileTask == nil {
57+
return e.String()
58+
}
59+
return "Compiling: " + e.Compile.SourcePath.String()
60+
}
61+
5462
func (e *detectorCacheEntry) Equals(entry *detectorCacheEntry) bool {
5563
return e.String() == entry.String()
5664
}
@@ -94,10 +102,15 @@ func (c *detectorCache) Expect(entry *detectorCacheEntry) {
94102
if c.entries[c.curr].Equals(entry) {
95103
// Cache hit, move to the next entry
96104
c.curr++
105+
logrus.Tracef("[LD] CACHE: HIT %s", entry.LogMsg())
97106
return
98107
}
99108
// Cache mismatch, invalidate and cut the remainder of the cache
109+
logrus.Tracef("[LD] CACHE: INVALIDATE %s", entry.LogMsg())
110+
logrus.Tracef("[LD] (was %s)", c.entries[c.curr])
100111
c.entries = c.entries[:c.curr]
112+
} else {
113+
logrus.Tracef("[LD] CACHE: MISSING %s", entry.LogMsg())
101114
}
102115
c.curr++
103116
c.entries = append(c.entries, entry)

‎internal/arduino/builder/internal/detector/detector.go‎

Lines changed: 15 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -41,6 +41,7 @@ import (
4141
"github.com/arduino/arduino-cli/internal/i18n"
4242
"github.com/arduino/go-paths-helper"
4343
"github.com/arduino/go-properties-orderedmap"
44+
"github.com/sirupsen/logrus"
4445
)
4546

4647
type libraryResolutionResult struct {
@@ -140,6 +141,7 @@ func (l *SketchLibrariesDetector) ImportedLibraries() libraries.List {
140141
// addAndBuildLibrary adds the given library to the imported libraries list and queues its source files
141142
// for further processing.
142143
func (l *SketchLibrariesDetector) addAndBuildLibrary(sourceFileQueue *uniqueSourceFileQueue, librariesBuildPath *paths.Path, library *libraries.Library) {
144+
logrus.Tracef("[LD] LIBRARY: %s", library.Name)
143145
l.importedLibraries = append(l.importedLibraries, library)
144146
if library.Precompiled && library.PrecompiledWithSources {
145147
// Fully precompiled libraries should have no dependencies to avoid ABI breakage
@@ -202,6 +204,7 @@ func (l *SketchLibrariesDetector) IncludeFoldersChanged() bool {
202204

203205
// addIncludeFolder add the given folder to the include path.
204206
func (l *SketchLibrariesDetector) addIncludeFolder(folder *paths.Path) {
207+
logrus.Tracef("[LD] INCLUDE-PATH: %s", folder.String())
205208
l.includeFolders = append(l.includeFolders, folder)
206209
l.cache.Expect(&detectorCacheEntry{AddedIncludePath: folder})
207210
}
@@ -219,6 +222,11 @@ func (l *SketchLibrariesDetector) FindIncludes(
219222
platformArch string,
220223
jobs int,
221224
) error {
225+
logrus.Debug("Finding required libraries for the sketch.")
226+
defer func() {
227+
logrus.Debugf("Library detection completed. Found %d required libraries.", len(l.importedLibraries))
228+
}()
229+
222230
err := l.findIncludes(ctx, buildPath, buildCorePath, buildVariantPath, sketchBuildPath, sketch, librariesBuildPath, buildProperties, platformArch, jobs)
223231
if err != nil && l.onlyUpdateCompilationDatabase {
224232
l.logger.Info(
@@ -273,7 +281,7 @@ func (l *SketchLibrariesDetector) findIncludes(
273281
l.preRunner = runner.New(ctx, jobs)
274282
for _, entry := range l.cache.EntriesAhead() {
275283
if entry.CompileTask != nil {
276-
upToDate, _ := entry.Compile.ObjFileIsUpToDate()
284+
upToDate, _ := entry.Compile.ObjFileIsUpToDate(logrus.WithField("runner", "prerun"))
277285
if !upToDate {
278286
_ = entry.Compile.PrepareBuildPath()
279287
l.preRunner.Enqueue(entry.CompileTask)
@@ -387,7 +395,7 @@ func (l *SketchLibrariesDetector) findMissingIncludesInCompilationUnit(
387395
// TODO: This reads the dependency file, but the actual building
388396
// does it again. Should the result be somehow cached? Perhaps
389397
// remove the object file if it is found to be stale?
390-
unchanged, err := sourceFile.ObjFileIsUpToDate()
398+
unchanged, err := sourceFile.ObjFileIsUpToDate(logrus.WithField("runner", "main"))
391399
if err != nil {
392400
return err
393401
}
@@ -403,11 +411,13 @@ func (l *SketchLibrariesDetector) findMissingIncludesInCompilationUnit(
403411
var missingIncludeH string
404412
if entry := l.cache.Peek(); unchanged && entry != nil && entry.MissingIncludeH != nil {
405413
missingIncludeH = *entry.MissingIncludeH
414+
logrus.Tracef("[LD] COMPILE-CACHE: %s", sourceFile.SourcePath)
406415
if first && l.logger.VerbosityLevel() == logger.VerbosityVerbose {
407416
l.logger.Info(i18n.Tr("Using cached library dependencies for file: %[1]s", sourcePath))
408417
}
409418
first = false
410419
} else {
420+
logrus.Tracef("[LD] COMPILE: %s", sourceFile.SourcePath)
411421
if l.preRunner != nil {
412422
if r := l.preRunner.Results(preprocTask); r != nil {
413423
preprocResult = r
@@ -448,6 +458,7 @@ func (l *SketchLibrariesDetector) findMissingIncludesInCompilationUnit(
448458
}
449459
}
450460

461+
logrus.Tracef("[LD] MISSING: %s", missingIncludeH)
451462
l.cache.Expect(&detectorCacheEntry{MissingIncludeH: &missingIncludeH})
452463

453464
if missingIncludeH == "" {
@@ -495,6 +506,8 @@ func (l *SketchLibrariesDetector) queueSourceFilesFromFolder(
495506
buildDir *paths.Path,
496507
extraIncludePath ...*paths.Path,
497508
) error {
509+
logrus.Tracef("[LD] SCAN: %s (recurse=%v)", folder, recurse)
510+
498511
sourceFileExtensions := []string{}
499512
for k := range globals.SourceFilesValidExtensions {
500513
sourceFileExtensions = append(sourceFileExtensions, k)

‎internal/arduino/builder/internal/detector/source_file.go‎

Lines changed: 13 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -62,60 +62,60 @@ func (f *sourceFile) PrepareBuildPath() error {
6262
}
6363

6464
// ObjFileIsUpToDate checks if the compile object file is up to date.
65-
func (f *sourceFile) ObjFileIsUpToDate() (unchanged bool, err error) {
66-
logrus.Debugf("Checking previous results for %v (dep = %v)", f.SourcePath, f.DepfilePath)
65+
func (f *sourceFile) ObjFileIsUpToDate(log *logrus.Entry) (unchanged bool, err error) {
6766
if f.DepfilePath == nil {
68-
logrus.Debugf(" Object file or dependency file not provided")
67+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: object file or dependency file not provided", f.SourcePath)
6968
return false, nil
7069
}
7170

7271
sourceFile := f.SourcePath.Clean()
7372
sourceFileStat, err := sourceFile.Stat()
7473
if err != nil {
75-
logrus.Debugf(" Could not stat source file: %s", err)
74+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: Could not stat source file: %s", f.SourcePath, err)
7675
return false, err
7776
}
7877
dependencyFile := f.DepfilePath.Clean()
7978
dependencyFileStat, err := dependencyFile.Stat()
8079
if err != nil {
8180
if os.IsNotExist(err) {
82-
logrus.Debugf(" Dependency file not found: %v", dependencyFile)
81+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: Dependency file not found: %v", f.SourcePath, dependencyFile)
8382
return false, nil
8483
}
85-
logrus.Debugf(" Could not stat dependency file: %s", err)
84+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: Could not stat dependency file: %s", f.SourcePath, err)
8685
return false, err
8786
}
8887
if sourceFileStat.ModTime().After(dependencyFileStat.ModTime()) {
89-
logrus.Debugf(" %v newer than %v", sourceFile, dependencyFile)
88+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: %v newer than %v", f.SourcePath, sourceFile, dependencyFile)
9089
return false, nil
9190
}
9291
deps, err := cpp.ReadDepFile(dependencyFile)
9392
if err != nil {
94-
logrus.Debugf(" Could not read dependency file: %s", dependencyFile)
93+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: Could not read dependency file: %s", f.SourcePath, dependencyFile)
9594
return false, err
9695
}
9796
if len(deps.Dependencies) == 0 {
9897
return true, nil
9998
}
10099
if deps.Dependencies[0] != sourceFile.String() {
101-
logrus.Debugf(" Depfile is about different source file: %v (expected %v)", deps.Dependencies[0], sourceFile)
100+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: Depfile is about different source file: %v (expected %v)", f.SourcePath, deps.Dependencies[0], sourceFile)
102101
return false, nil
103102
}
104103
for _, dep := range deps.Dependencies[1:] {
105104
depStat, err := os.Stat(dep)
106105
if os.IsNotExist(err) {
107-
logrus.Debugf(" Not found: %v", dep)
106+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: Not found: %v", f.SourcePath, dep)
108107
return false, nil
109108
}
110109
if err != nil {
111-
logrus.WithError(err).Debugf(" Failed to read: %v", dep)
110+
logrus.WithError(err).Tracef("[LD] COMPILE-CHECK: REBUILD %v: Failed to read: %v", f.SourcePath, dep)
112111
return false, nil
113112
}
114113
if depStat.ModTime().After(dependencyFileStat.ModTime()) {
115-
logrus.Debugf(" %v newer than %v", dep, dependencyFile)
114+
log.Tracef("[LD] COMPILE-CHECK: REBUILD %v: %v newer than %v", f.SourcePath, dep, dependencyFile)
116115
return false, nil
117116
}
118117
}
118+
log.Tracef("[LD] COMPILE-CHECK: REUSE %v Up-to-date", f.SourcePath)
119119
return true, nil
120120
}
121121

@@ -125,6 +125,7 @@ type uniqueSourceFileQueue []sourceFile
125125
// Push adds a source file to the queue if it is not already present.
126126
func (queue *uniqueSourceFileQueue) Push(value sourceFile) {
127127
if !queue.Contains(value) {
128+
logrus.Tracef("[LD] QUEUE: Added %s", value.SourcePath)
128129
*queue = append(*queue, value)
129130
}
130131
}

0 commit comments

Comments
 (0)