Add dtrace provider 'afp' and dtrace probes

There are three dtrace probes:
- all AFP functions, passing the function name as argument
- AFP read and write, passing the IO size as argument
- all CNID functions

In order to be able to simply differintiate between disk IO and
network IO, replace all occurences of read and write on sockets
with send/recv, and replace the use of writev in the logging code
with two calls to write.
As a result, using dtrace probes for read() and write() syscalls
can be used to gather metrics for disk IO, while probing send(),
recv() and writev() probe network IO.

Makefile.am

@@ -1,9 +1,9 @@
 # Makefile.am for top level of netatalk package
 
 if USE_BUILTIN_LIBEVENT
-SUBDIRS = libevent libatalk bin config etc man contrib distrib include doc macros test
+SUBDIRS = libevent include libatalk bin config etc man contrib distrib doc macros test
 else
-SUBDIRS = libatalk bin config etc man contrib distrib include doc macros test
+SUBDIRS = include libatalk bin config etc man contrib distrib doc macros test
 endif
 
 EXTRA_DIST = CONTRIBUTORS COPYRIGHT COPYING NEWS VERSION

NEWS

@@ -19,6 +19,8 @@ Changes in 3.0.3
        program `afpstats`. Requires dbus, dbus-glib any python-dbus.
        configure option --dbus-sysconf-dir for specifying dbus
        system security configuration files.       
+* NEW: dtrace probes, cf include/atalk/afp_dtrace.d for available
+       probes.
 
 Changes in 3.0.2
 ================

configure.ac

@@ -183,16 +183,19 @@ AC_NETATALK_LIBEVENT
 dnl libatalk API checks
 AC_DEVELOPER
 
+dnl Check for dtrace
+AC_NETATALK_DTRACE
+
+dnl Check for dbus-glib, for AFP stats on dbus
+AC_NETATALK_DBUS_GLIB
+
 dnl FHS stuff has to be done last because it overrides other defaults
 AC_NETATALK_FHS
 
 dnl netatalk lockfile path, must come after AC_NETATALK_FHS
 AC_NETATALK_LOCKFILE
 
-dnl Check for dbus-glib, for AFP stats on dbus
-AC_NETATALK_DBUS_GLIB
-
-CFLAGS="-I\$(top_srcdir)/include -I\$(top_srcdir)/sys $CFLAGS"
+CFLAGS="-I\$(top_srcdir)/include -I\$(top_builddir)/include $CFLAGS"
 UAMS_PATH="${uams_path}"
 
 AC_SUBST(LIBS)

etc/afpd/Makefile.am

@@ -46,6 +46,7 @@ afpd_SOURCES = \
 	unix.c \
 	volume.c
 
+
 afpd_LDADD =  \
 	$(top_builddir)/libatalk/libatalk.la \
 	@LIBGCRYPT_LIBS@ @QUOTA_LIBS@ @WRAP_LIBS@ @LIBADD_DL@ @ACL_LIBS@ @ZEROCONF_LIBS@ @PTHREAD_LIBS@ @GSSAPI_LIBS@ @KRB5_LIBS@
@@ -83,6 +84,15 @@ afpd_CFLAGS  += $(DBUS_CFLAGS) $(DBUS_GLIB_CFLAGS) -DDBUS_COMPILATION
 afpd_LDFLAGS += $(DBUS_LIBS) $(DBUS_GLIB_LIBS) -ldbus-glib-1
 endif
 
+if WITH_DTRACE
+DTRACE_OBJ = afpd-afp_dsi.o afpd-fork.o afpd-appl.o afpd-catsearch.o afpd-directory.o afpd-enumerate.o afpd-file.o afpd-filedir.o
+afp_dtrace.o: $(top_srcdir)/include/atalk/afp_dtrace.d $(DTRACE_OBJ)
+	if test -f afp_dtrace.o ; then rm -f afp_dtrace.o ; fi
+	$(LIBTOOL) --mode=execute dtrace -G -s $(top_srcdir)/include/atalk/afp_dtrace.d -o afp_dtrace.o $(DTRACE_OBJ)
+afpd_LDADD += afp_dtrace.o @DTRACE_LIBS@
+CLEANFILES += afp_dtrace.o
+endif
+
 noinst_HEADERS = auth.h afp_config.h desktop.h directory.h fce_api_internal.h file.h \
 	 filedir.h fork.h icon.h mangle.h misc.h status.h switch.h \
 	 uam_auth.h uid.h unix.h volume.h hash.h acls.h acl_mappings.h extattrs.h \

etc/afpd/afp_dsi.c

@@ -603,10 +603,12 @@ void afp_over_dsi(AFPObj *obj)
 
                     LOG(log_debug, logtype_afpd, "<== Start AFP command: %s", AfpNum2name(function));
 
+                    AFP_AFPFUNC_START(function, (char *)AfpNum2name(function));
                     err = (*afp_switch[function])(obj,
                                                   (char *)dsi->commands, dsi->cmdlen,
                                                   (char *)&dsi->data, &dsi->datalen);
 
+                    AFP_AFPFUNC_DONE(function, (char *)AfpNum2name(function));
                     LOG(log_debug, logtype_afpd, "==> Finished AFP command: %s -> %s",
                         AfpNum2name(function), AfpErr2name(err));
 
@@ -644,10 +646,14 @@ void afp_over_dsi(AFPObj *obj)
 
                 LOG(log_debug, logtype_afpd, "<== Start AFP command: %s", AfpNum2name(function));
 
+                AFP_AFPFUNC_START(function, (char *)AfpNum2name(function));
+
                 err = (*afp_switch[function])(obj,
                                               (char *)dsi->commands, dsi->cmdlen,
                                               (char *)&dsi->data, &dsi->datalen);
 
+                AFP_AFPFUNC_DONE(function, (char *)AfpNum2name(function));
+
                 LOG(log_debug, logtype_afpd, "==> Finished AFP command: %s -> %s",
                     AfpNum2name(function), AfpErr2name(err));
 

etc/afpd/appl.c

@@ -170,7 +170,11 @@ makemacpath(const struct vol *vol, char *mpath, int mpathlen, struct dir *dir, c
         }
 
         /* next part */
-        if ((uname = cnid_resolve(vol->v_cdb, &cnid, buffer, buflen)) == NULL ) {
+        AFP_CNID_START("cnid_resolve");
+        uname = cnid_resolve(vol->v_cdb, &cnid, buffer, buflen);
+        AFP_CNID_DONE();
+
+        if (uname == NULL) {
             afp_errno = AFPERR_NOOBJ;
             ret = NULL;
             goto exit;

etc/afpd/catsearch.c

@@ -743,11 +743,14 @@ static int catsearch_db(const AFPObj *obj,
 
         LOG(log_debug, logtype_afpd, "catsearch_db: %s", buffer);
 
-        if ((num_matches = cnid_find(vol->v_cdb,
-                                     buffer,
-                                     strlen(uname),
-                                     resbuf,
-                                     sizeof(resbuf))) == -1) {
+        AFP_CNID_START("cnid_find");
+        num_matches = cnid_find(vol->v_cdb,
+                                buffer,
+                                strlen(uname),
+                                resbuf,
+                                sizeof(resbuf));
+        AFP_CNID_DONE();
+        if (num_matches == -1) {
             result = AFPERR_MISC;
             goto catsearch_end;
         }
@@ -763,8 +766,12 @@ static int catsearch_db(const AFPObj *obj,
         memcpy(&cnid, resbuf + cur_pos * sizeof(cnid_t), sizeof(cnid_t));
         did = cnid;
 
-        if ((name = cnid_resolve(vol->v_cdb, &did, resolvebuf, 12 + MAXPATHLEN + 1)) == NULL)
+        AFP_CNID_START("cnid_resolve");
+        name = cnid_resolve(vol->v_cdb, &did, resolvebuf, 12 + MAXPATHLEN + 1);
+        AFP_CNID_DONE();
+        if (name == NULL)
             goto next;
+
         LOG(log_debug, logtype_afpd, "catsearch_db: {pos: %u, name:%s, cnid: %u}",
             cur_pos, name, ntohl(cnid));
         if ((dir = dirlookup(vol, did)) == NULL)

etc/afpd/directory.c

@@ -497,12 +497,15 @@ struct dir *dirlookup_bypath(const struct vol *vol, const char *path)
                                            cfrombstr(l->entry[i]),
                                            blength(l->entry[i]))) == NULL) {
 
-            if ((cnid = cnid_add(vol->v_cdb,             /* 6. */
-                                 &st,
-                                 did,
-                                 cfrombstr(l->entry[i]),
-                                 blength(l->entry[i]),
-                                 0)) == CNID_INVALID)
+            AFP_CNID_START("cnid_add");
+            cnid = cnid_add(vol->v_cdb,             /* 6. */
+                            &st,
+                            did,
+                            cfrombstr(l->entry[i]),
+                            blength(l->entry[i]),
+                            0);
+            AFP_CNID_DONE();
+            if (cnid == CNID_INVALID)
                 EC_FAIL;
 
             if ((dir = dirlookup(vol, cnid)) == NULL) /* 7. */
@@ -607,7 +610,11 @@ struct dir *dirlookup(const struct vol *vol, cnid_t did)
     /* Get it from the database */
     cnid = did;
     LOG(log_debug, logtype_afpd, "dirlookup(did: %u): querying CNID database", ntohl(did));
-    if ((upath = cnid_resolve(vol->v_cdb, &cnid, buffer, buflen)) == NULL) {
+
+    AFP_CNID_START("cnid_resolve");
+    upath = cnid_resolve(vol->v_cdb, &cnid, buffer, buflen);
+    AFP_CNID_DONE();
+    if (upath == NULL) {
         afp_errno = AFPERR_NOOBJ;
         err = 1;
         goto exit;
@@ -2329,7 +2336,9 @@ int deletecurdir(struct vol *vol)
 
     err = netatalk_rmdir_all_errors(-1, cfrombstr(fdir->d_u_name));
     if ( err ==  AFP_OK || err == AFPERR_NOOBJ) {
+        AFP_CNID_START("cnid_delete");
         cnid_delete(vol->v_cdb, fdir->d_did);
+        AFP_CNID_DONE();
         dir_remove( vol, fdir );
     } else {
         LOG(log_error, logtype_afpd, "deletecurdir(\"%s\"): netatalk_rmdir_all_errors error",

etc/afpd/enumerate.c

@@ -365,9 +365,14 @@ static int enumerate(AFPObj *obj _U_, char *ibuf, size_t ibuflen _U_,
         if (ad_convert(sd.sd_last, &s_path.st, vol, &convname) == 0) {
             if (convname) {
                 s_path.u_name = (char *)convname;
+                AFP_CNID_START("cnid_lookup");
                 s_path.id = cnid_lookup(vol->v_cdb, &s_path.st, curdir->d_did, sd.sd_last, strlen(sd.sd_last));
+                AFP_CNID_DONE();
                 if (s_path.id != CNID_INVALID) {
-                    if (cnid_update(vol->v_cdb, s_path.id, &s_path.st, curdir->d_did, (char *)convname, strlen(convname)) != 0)
+                    AFP_CNID_START("cnid_update");
+                    int cnid_up_ret = cnid_update(vol->v_cdb, s_path.id, &s_path.st, curdir->d_did, (char *)convname, strlen(convname));
+                    AFP_CNID_DONE();
+                    if (cnid_up_ret != 0)
                         LOG(log_error, logtype_afpd, "enumerate: error updating CNID of \"%s\"", fullpathname(convname));
                 }
             }

etc/afpd/file.c

@@ -219,7 +219,10 @@ uint32_t get_id(struct vol *vol,
            catching moved files */
         adcnid = ad_getid(adp, st->st_dev, st->st_ino, 0, vol->v_stamp); /* (1) */
 
+        AFP_CNID_START("cnid_add");
 	    dbcnid = cnid_add(vol->v_cdb, st, did, upath, len, adcnid); /* (2) */
+        AFP_CNID_DONE();
+
 	    /* Throw errors if cnid_add fails. */
 	    if (dbcnid == CNID_INVALID) {
             switch (errno) {
@@ -1602,8 +1605,15 @@ int deletefile(const struct vol *vol, int dirfd, char *file, int checkAttrib)
         err = AFPERR_BUSY;
     } else if (!(err = vol->vfs->vfs_deletefile(vol, dirfd, file)) && !(err = netatalk_unlinkat(dirfd, file )) ) {
         cnid_t id;
-        if (checkAttrib && (id = cnid_get(vol->v_cdb, curdir->d_did, file, strlen(file)))) {
-            cnid_delete(vol->v_cdb, id);
+        if (checkAttrib) {
+            AFP_CNID_START("cnid_get");
+            id = cnid_get(vol->v_cdb, curdir->d_did, file, strlen(file));
+            AFP_CNID_DONE();
+            if (id) {
+                AFP_CNID_START("cnid_delete");
+                cnid_delete(vol->v_cdb, id);
+                AFP_CNID_DONE();
+            }
         }
     }
 
@@ -1676,7 +1686,10 @@ int afp_createid(AFPObj *obj _U_, char *ibuf, size_t ibuflen _U_, char *rbuf, si
             return AFPERR_PARAM;
     }
     st = &s_path->st;
-    if ((id = cnid_lookup(vol->v_cdb, st, did, upath, len = strlen(upath)))) {
+    AFP_CNID_START("cnid_lookup");
+    id = cnid_lookup(vol->v_cdb, st, did, upath, len = strlen(upath));
+    AFP_CNID_DONE();
+    if (id) {
         memcpy(rbuf, &id, sizeof(id));
         *rbuflen = sizeof(id);
         return AFPERR_EXISTID;
@@ -1709,7 +1722,9 @@ static int reenumerate_loop(struct dirent *de, char *mname _U_, void *data)
         return 0;
 
     /* update or add to cnid */
+    AFP_CNID_START("cnid_add");
     aint = cnid_add(vol->v_cdb, &path.st, did, de->d_name, strlen(de->d_name), 0); /* ignore errors */
+    AFP_CNID_DONE();
 
     return 0;
 }
@@ -1788,7 +1803,10 @@ int afp_resolveid(AFPObj *obj, char *ibuf, size_t ibuflen _U_, char *rbuf, size_
         return AFPERR_NOID;
     }
 retry:
-    if (NULL == (upath = cnid_resolve(vol->v_cdb, &id, buffer, len)) ) {
+    AFP_CNID_START("cnid_resolve");
+    upath = cnid_resolve(vol->v_cdb, &id, buffer, len);
+    AFP_CNID_DONE();
+    if (upath == NULL) {
         return AFPERR_NOID; /* was AFPERR_BADID, but help older Macs */
     }
 
@@ -1891,7 +1909,10 @@ int afp_deleteid(AFPObj *obj _U_, char *ibuf, size_t ibuflen _U_, char *rbuf _U_
     ibuf += sizeof(id);
     fileid = id;
 
-    if (NULL == (upath = cnid_resolve(vol->v_cdb, &id, buffer, len)) ) {
+    AFP_CNID_START("cnid_resolve");
+    upath = cnid_resolve(vol->v_cdb, &id, buffer, len);
+    AFP_CNID_DONE();
+        if (upath == NULL) {
         return AFPERR_NOID;
     }
 
@@ -1924,7 +1945,9 @@ int afp_deleteid(AFPObj *obj _U_, char *ibuf, size_t ibuflen _U_, char *rbuf _U_
         return AFPERR_BADTYPE;
 
 delete:
+    AFP_CNID_START("cnid_delete");
     if (cnid_delete(vol->v_cdb, fileid)) {
+        AFP_CNID_DONE();
         switch (errno) {
         case EROFS:
             return AFPERR_VLOCK;
@@ -1935,7 +1958,7 @@ int afp_deleteid(AFPObj *obj _U_, char *ibuf, size_t ibuflen _U_, char *rbuf _U_
             return AFPERR_PARAM;
         }
     }
-
+    AFP_CNID_DONE();
     return err;
 }
 
@@ -2063,7 +2086,9 @@ int afp_exchangefiles(AFPObj *obj, char *ibuf, size_t ibuflen _U_, char *rbuf _U
 
     /* look for the source cnid. if it doesn't exist, don't worry about
      * it. */
+    AFP_CNID_START("cnid_lookup");
     sid = cnid_lookup(vol->v_cdb, &srcst, sdir->d_did, supath,slen = strlen(supath));
+    AFP_CNID_DONE();
 
     if (NULL == ( dir = dirlookup( vol, did )) ) {
         err = afp_errno; /* was AFPERR_PARAM */
@@ -2106,7 +2131,9 @@ int afp_exchangefiles(AFPObj *obj, char *ibuf, size_t ibuflen _U_, char *rbuf _U
 
     /* look for destination id. */
     upath = path->u_name;
+    AFP_CNID_START("cnid_lookup");
     did = cnid_lookup(vol->v_cdb, &destst, curdir->d_did, upath, dlen = strlen(upath));
+    AFP_CNID_DONE();
 
     /* construct a temp name.
      * NOTE: the temp file will be in the dest file's directory. it
@@ -2140,13 +2167,20 @@ int afp_exchangefiles(AFPObj *obj, char *ibuf, size_t ibuflen _U_, char *rbuf _U
         goto err_dest_to_src;
     of_rename(vol, s_of, curdir, temp, curdir, path->m_name);
 
-    /* id's need switching. src -> dest and dest -> src. 
+    /* 
+     * id's need switching. src -> dest and dest -> src. 
      * we need to re-stat() if it was a cross device copy.
-    */
-    if (sid)
+     */
+    if (sid) {
+        AFP_CNID_START("cnid_delete");        
         cnid_delete(vol->v_cdb, sid);
-    if (did)
+        AFP_CNID_DONE();
+    }
+    if (did) {
+        AFP_CNID_START("cnid_delete");
         cnid_delete(vol->v_cdb, did);
+        AFP_CNID_DONE();
+    }
 
     if ((did && ( (crossdev && ostat(upath, &srcst, vol_syml_opt(vol)) < 0) || 
                 cnid_update(vol->v_cdb, did, &srcst, curdir->d_did,upath, dlen) < 0))

etc/afpd/filedir.c

@@ -248,7 +248,9 @@ static int moveandrename(struct vol *vol,
     if (!isdir) {
         if ((oldunixname = strdup(mtoupath(vol, oldname, sdir->d_did, utf8_encoding(vol->v_obj)))) == NULL)
             return AFPERR_PARAM; /* can't convert */
+        AFP_CNID_START("cnid_get");
         id = cnid_get(vol->v_cdb, sdir->d_did, oldunixname, strlen(oldunixname));
+        AFP_CNID_DONE();
 
 #ifndef HAVE_ATFUNCS
         /* Need full path */
@@ -378,7 +380,9 @@ static int moveandrename(struct vol *vol,
         }
 
         /* fix up the catalog entry */
+        AFP_CNID_START("cnid_update");
         cnid_update(vol->v_cdb, id, st, curdir->d_did, upath, strlen(upath));
+        AFP_CNID_DONE();
     }
 
 exit:
@@ -521,10 +525,16 @@ int afp_delete(AFPObj *obj, char *ibuf, size_t ibuflen _U_, char *rbuf _U_, size
                 delcnid = deldir->d_did;
                 dir_remove(vol, deldir);
             }
-            if (delcnid == CNID_INVALID)
+            if (delcnid == CNID_INVALID) {
+                AFP_CNID_START("cnid_get");
                 delcnid = cnid_get(vol->v_cdb, curdir->d_did, upath, strlen(upath));
-            if (delcnid != CNID_INVALID)
+                AFP_CNID_DONE();
+            }
+            if (delcnid != CNID_INVALID) {
+                AFP_CNID_START("cnid_delete");
                 cnid_delete(vol->v_cdb, delcnid);
+                AFP_CNID_DONE();
+            }
             fce_register(FCE_DIR_DELETE, fullpathname(upath), NULL, fce_dir);
         } else {
             /* we have to cache this, the structs are lost in deletcurdir*/